Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> Many thanks you fixed the issue. May I consult you the theory of your
> fixing? Does au_wkq_wait() put vfs_read to an interrupt free stat so that
> read can complete without interrupt error? Just curious.

Many thanx to you for your repeated tests.
The workqueue is a kernel thread, and aufs often passes the workqueue a
certain operaion and wait for its completion, sometimes doesn't wait.
No one should send SIGKILL to the workqueue, so the workqueue always be
able to read the XINO file without being bothered fatal_signal_pending()
test in do_generic_file_read().

FYI, here is a commit log for the patch.
--
aufs: for v4.10, XINO(read) handles EINTR from the dying process

The commit in linux-v4.10-rc7
5abf186 2017-02-03 mm, fs: check for fatal signals in 
do_generic_file_read()
will make aufs hung-up under a certain condition.
The condition is (roughly)
- linux-v4.10-rc7 and later.
- aufs has many files (over 32K inode-numbers are assigned).
- the process is killed by SIGKILL.
- the dying process held a unliked file whose inode-number is cold.
  here "cold" means out of aufs internal XINO bitmap cache. so aufs has
  to read XINO bitmap from a disk in order to maintain the bitmap.
- the fs where XINO files are placed calls do_generic_file_read() to
  imprelent its ->read().

In linux-v4.3, the was a very similar situation by the commit
296291c 2015-10-23 mm: make sendfile(2) killable
but it was "write to XINO" instead of "read from XINO" case.
And it was fixed by the commit
5e439ff 2016-01-05 aufs: for 4.3, XINO handles EINTR from the dying 
process
which made aufs4.3 retries "write to XINO" in another context after
EINTR.

Here the same approach is applied to the case of "read from XINO."

Reported-by: Eddie Horng 
Tested-by: Eddie Horng 
--


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> The patch works great! Applied the patch I can't reproduce the problem
> anymore, when func(file, buf.u, size, pos) returns -EINTR, "if (err ==
> -EINTR && !au_wkq_test() ..." entered and I never see i>1 case. Is this
> patch the final solution for this case?

Glad to hear that!
Well, the patch is final, I think. But as you mentioned, i>1 case should
not happen as far as I know. But I'd leave it as it is since it is
something like a safe-guard for some unknown/future case like this
problem.


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> I doubt that clang++.real has special file i/o or some signal handling that
> trigger the scenario, there're many kinds of processes are running in
> android building but the only busy looping process is always the same one
> in all my reproducing test. BTW, the return value from " err = func(file,
> buf.u, size, pos);  " is -4, for your reference. I'll test the patch by Mon.

Ok, 4 is EINTR.
As you gueesed, clang++ may send SIGKILL to his children(process or
thread) and it may cause the problem.
I'm looking forward to read your report.

Thanx
J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> It seems all tasks are trying to lock sbinfo->si_xib_mtx, but log shows
> nobody is holding it. I also got similar problem in my codefs, but it's
> very rare, not like this case now I can almost always reproduce it. To
> isolate issue, I changed ro branch from codefs to ext4 and still can
> reproduce.
> List reproduce step as below, maybe can give you some hint:
> - The codebase is an android source package
> - make -j128 (found -j32 can also repro)
> - ctrl-c to interrupt build
> - the build system -- ninja will kill all subprocesses
> - In most case a clang++.real process will left running forever with high
> cpu%

It looks a livelock (instead of a deadlock).
Still I cannot see the whole scenario, but I've found a suspicious, ah
no, "related" commit in linux-v4.10-rc7
5abf186 2017-02-03 mm, fs: check for fatal signals in 
do_generic_file_read()

For aufs, the side effect of this commit is very similar to your
problem. It will cause a livelock in aufs and will happen in reading
from aufs XINO files.

There was a similar commit in linux-v4.3, but it was "write to XINO"
instead of "read from XINO" case.
296291c 2015-10-23 mm: make sendfile(2) killable
and I fixed it by the commit
5e439ff 2016-01-05 aufs: for 4.3, XINO handles EINTR from the dying 
process
which made aufs4.3 retries "write to XINO" in another context after
EINTR.

Hmm, if the cause of your problem is the endless loop after EINTR in
"read from XINO", then it should be solved by the same approach which
aufs4.3. It requilres a small conversion "write to / read from" XINO.

The conditions to reproduce the problem should be like these.
- linux-v4.10-rc7 and later
- aufs has many files (over 32K)
- the process is killed by SIGKILL

I've tried, but I could not reproduce the problem in the beginning...
I'd ask you to test this patch. If you can, please try.


J. R. Okajima



a.patch.bz2
Description: BZip2 compressed data
--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> Log attached - related to previous mail

Thanx a lot.
But unfortunately there was not good info in the log.
I am still reviewing my aufs code. At the same time I start wondering
the problem may exist out of aufs. I know such probability is very
small.

Reviewing the code, I will prepare the test environment on ubuntu
kernel. It will take some time. Additionally I will be offline next
week.
So my next response will be a few week later. Sorry for your
inconvenient.


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> Thanks the information, but I still can reproduce it with aufs-4.10 and the
> held lock patch.

Hmm...
I am totally confused and lost my way. I don't understand what is
happening. If anyone on this list has an idea which light up the way, I
will be gladly become all ears.

Your report can be summarized as

   41.315960 aufs 4.10-20171002
:::
 ninjaD  0   3376 1 0x0004
 Call Trace:
   __schedule+0x2db/0x910
   ? schedule+0x3d/0x90
   schedule+0x3d/0x90
   schedule_preempt_disabled+0x15/0x20
   mutex_lock_nested+0x21f/0x5d0
   ? au_xino_delete_inode+0x1a3/0x1f0 aufs
   ? xino_fwrite+0xa0/0xb0 aufs
   au_xino_delete_inode+0x1a3/0x1f0 aufs
   au_iinfo_fin+0x100/0x130 aufs
   aufs_destroy_inode+0x47/0x50 aufs
   destroy_inode+0x3b/0x60
   evict+0x132/0x190
   iput+0x1f8/0x280
   do_unlinkat+0x18f/0x2d0
   SyS_unlink+0x16/0x20
   entry_SYSCALL_64_fastpath+0x1e/0xb2
:::
 clang++.real  D  0   6173 1 0x0006
 Call Trace:
   __schedule+0x2db/0x910
   ? mutex_spin_on_owner+0xb1/0xd0
   ? mutex_spin_on_owner+0x5/0xd0
   schedule+0x3d/0x90
   schedule_preempt_disabled+0x15/0x20
   mutex_lock_nested+0x21f/0x5d0
   ? au_xino_delete_inode+0x1a3/0x1f0 aufs
   au_xino_delete_inode+0x1a3/0x1f0 aufs
   au_iinfo_fin+0x100/0x130 aufs
   aufs_destroy_inode+0x47/0x50 aufs
   destroy_inode+0x3b/0x60
   evict+0x132/0x190
   iput+0x1f8/0x280
   dentry_unlink_inode+0xc3/0x160
   __dentry_kill+0xc6/0x170
   dput+0x1ea/0x310
   ? dput+0x29/0x310
   __fput+0x19e/0x240
   fput+0xe/0x10
   task_work_run+0x7e/0xb0
   do_exit+0x323/0xbe0
   ? __sigqueue_free.part.20+0x33/0x40
   do_group_exit+0x50/0xd0
   get_signal+0x2be/0x720
   do_signal+0x28/0x770
   exit_to_usermode_loop+0x76/0xb0
   syscall_return_slowpath+0x62/0x70
   entry_SYSCALL_64_fastpath+0xb0/0xb2
:::
 Showing all locks held in the system:
 3 locks held by ninja/3376:
   #0:   (sb_writers#18) mnt_want_write+0x24/0x50
   #1:   (>si_rwsem) au_iinfo_fin+0xec/0x130 aufs
   #2:   (>si_xib_mtx) au_xino_delete_inode+0x1a3/0x1f0 aufs
 2 locks held by clang++.real/6173:
   #0:   (>si_rwsem) au_iinfo_fin+0xec/0x130 aufs
   #1:   (>si_xib_mtx) au_xino_delete_inode+0x1a3/0x1f0 aufs


These two processes have the very similar call stack. The common part is
   mutex_lock_nested
   au_xino_delete_inode
   au_iinfo_fin
   aufs_destroy_inode
   destroy_inode
   evict
   iput

And the lockdep reports the suspicious mutex is sbinfo->si_xib_mtx in
aufs. But I cannot find any problem around it.


Eddie, I appriciate your repeated tests. It may be hard for you.
But I have another request. Try enabling CONFIG_AUFS_DEBUG and
reprducing the problem. Of course, I know that I should add "if you can,
please" magic words.


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

> But I have a suggestion for you.
>
> 1. upgrade your aufs to the latest aufs4.10.
>This is my very best recommendation.
:::

Ah, I forgot one thing.
Here is a debug patch to see the problem more clearly.
This is not a fix, but it may help to see more in the held lock list.


J. R. Okajima



a.patch.bz2
Description: BZip2 compressed data
--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

sf...@users.sourceforge.net:
> Exactly.
> At the same time, I noticed that I made a mistake on my git-work. I
> thought there is something wrong with the commit
>   e14748e 2017-02-19 UBUNTU: SAUCE: Import aufs driver
> in zesty because it doesn't match the commit
>   6c73f3b 2017-02-04 aufs4.x-rcN 20170206
> in aufs4-standalone.
> But it perfectly matches. I think I made some changes in zesty tree
> unwillingly during investigating this problem.
> Sorry for the confusion.
>
> But the conclusion doesn't change.
> I think you found a AB-BA deadlock problem in aufs, and I am working on
> it.

I might be confused again.
I cannot see the deadclok now which I thought I could find.
But I have a suggestion for you.

1. upgrade your aufs to the latest aufs4.10.
   This is my very best recommendation.

2. pick some commits from the latest aufs4.10.
   They *may* be related to your problem (but I am not sure).

   - a2e2715 2017-04-03 aufs: fine-grained xino lock 2/2, caller
   - 2356cdf 2017-04-03 aufs: fine-grained xino lock 1/2, callee
 These two commits are the first candidates I guessed at first. But
 I could not confirm that they could solve your problem. Anyway I
 believe it is worth to try.
 I am afraid that individual git-cherry-pick won't be enough since
 some other commits will be necessary (so my recommendation is
 upgrade the latest aufs4.10).

   - f1fa217 2017-09-05 aufs: bugfix, fanotify
 The caused stack trace by this fixed bug looks very similar to
 yours. But this bug is triggered by fanotify, and I don't think you
 are using it.

Here is all aufs4.10 commits after your version.
Obviously the base version of Ubuntu-4.10.0-34.38
6c73f3b 2017-02-04 aufs4.x-rcN 20170206
shoule be between
8b3d2df 2017-02-13 aufs: convert pid bitmap to a flag per task
7d3e718 2017-01-31 aufs: for linux-v4.10-rc1, replace au_match_ull() by 
new match_u64()

But it doesn't appear in this list since 6c73f3b is a history of
aufs4.x-rcN branch instead of aufs4.10.

47e483c 2017-12-16 aufs4.10 20171218
b05d081 2017-12-16 aufs: remove a warning about the internal file-close
1a10303 2017-10-26 aufs4.10 20171030
9654464 2017-10-26 aufs: possible bugfix, always call destroy_work_on_stack()
ee6cf53 2017-10-26 aufs: missing path_noexec() call
dc2e3f5 2017-10-26 aufs: cosmetic changes in some header files
8650a46 2017-10-09 aufs: tiny optimization for !CONFIG_AUFS_BR_HFSPLUS
c7dc5c1 2017-09-28 aufs4.10 20171002
551d63f 2017-09-28 aufs: tiny, refine a header inclusion
b49ea77 2017-09-28 aufs: tiny, silence checkpatch.pl
394717b 2017-09-22 aufs4.10 20170925
2f04618 2017-09-19 aufs: minor, use the new func is_current_mnt_ns()
803b86d 2017-09-19 aufs: possible bugfix, deref RCU ptr, current->real_parent
2310344 2017-09-15 aufs4.10 20170918
12b1b36 2017-09-15 aufs standalone: tiny, DIRREN configuration
f18e761 2017-09-12 aufs: minor, for v4.10, force casting the type of be64
5b9899d 2017-09-12 aufs: dirren 6/6, mount options
f1581ed 2017-09-12 aufs: dirren 5/6, lookup and revalidate with loading the 
rename info
4962685 2017-09-12 aufs: dirren 4/6, rename with saving the rename info
652f3f9 2017-09-12 aufs: dirren 3/6, save the detailed info per a dir
f0a6841 2017-09-12 aufs: dirren 2/6, branch id as a filename of the info
d1f4e7e 2017-09-12 aufs standalone: tiny, conf.mk for dirren
ba93f60 2017-09-12 aufs: dirren 1/6, inum-list of the renamed dir in a branch
d0d523e 2017-09-11 aufs: dirren 0/6, documentation
a2614a2 2017-09-11 aufs: tiny, move a few vars into the internal struct
92564ef 2017-09-11 aufs: minor, warn about some mount options
9272692 2017-09-11 aufs: minor, convert sphl (spinlock+hlist) to hbl (hlist_bl)
5329065 2017-09-08 aufs4.10 20170911
f1fa217 2017-09-05 aufs: bugfix, fanotify
dd18998 2017-09-04 aufs: tiny, convert kzalloc into kcalloc
363512b 2017-09-04 aufs: tiny, wrap around a long line
8bab339 2017-09-04 aufs: tiny, wrap around a long line
1559f56 2017-09-04 aufs: tiny, add a comment for the memory barrier
f8d6f94 2017-09-04 aufs: tiny, remove a few unnecessary 'if's for kfree()
88c077e 2017-09-01 aufs4.10 20170904
b59f1a6 2017-08-28 aufs: minor, for v4.7, more inode_lock_shared()
8e360a8 2017-08-28 aufs: tiny, complment a few missing declarations
ff46f23 2017-08-28 aufs: tiny, add a pronunciation in the document "intro"
a19543b 2017-06-30 aufs4.10 20170703
32e544a 2017-06-30 aufs: tiny, update the document "intro"
846bbd0 2017-06-11 aufs4.10 20170612
e34c81f 2017-06-09 aufs: bugfix, for v4.10, copy-up on XFS branch
ce82d66 2017-06-07 aufs: cosmetic changes
2de56bb 2017-05-21 aufs4.10 20170522
2169726 2017-05-18 aufs: possible bugfix, fput after using inode
2f39a63 2017-05-18 aufs: tiny, simplify au_seq_path
a34799a 2017-05-18 aufs: remove an unnecessary EXECed check for dir
4383c11 2017-05-18 aufs: remove the delayed free
eef3b3e 2017-05-18 aufs: tiny, remove an unnecessary declaration
f7c5117 2017-04-09 aufs4.10 20170410
a2e2715 2017-04-03 

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> Yes, my kernel is git://kernel.ubuntu.com/ubuntu/ubuntu-zesty.git @tag:
> Ubuntu-4.10.0-34.38.
> I diff fs/aufs from my codebase, changes from zesty#1bfb6eb and
> aufs4#6c73f3b are:
> fs/aufs/cpup.c
> fs/aufs/vfsub.h
> for your reference if these diffs are as you expected.

Exactly.
At the same time, I noticed that I made a mistake on my git-work. I
thought there is something wrong with the commit
e14748e 2017-02-19 UBUNTU: SAUCE: Import aufs driver
in zesty because it doesn't match the commit
6c73f3b 2017-02-04 aufs4.x-rcN 20170206
in aufs4-standalone.
But it perfectly matches. I think I made some changes in zesty tree
unwillingly during investigating this problem.
Sorry for the confusion.

But the conclusion doesn't change.
I think you found a AB-BA deadlock problem in aufs, and I am working on
it.



> From: Eddie Horng 
> Date: Tue, 23 Jan 2018 13:25:01 +0800
> 
> Occasionally I reproduced log as below, similar call stack but different
> lockdep message. Do you think this is different case or lockdep did not
> collect correct lock information?

It looks the same issue.


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Eddie Horng:
> I reproduced a hung case, maybe not exactly the same operation as original
> one but au_xino_delete_inode is appeared in call stake. Below dmesg log
> with lockdep enabled, please kindly check it.

Ok, I think I can find the AB-BA deadlock problem.
I will try fixing it asap. Please wait for a while.


BTW I was really confused about your kernel version. You wrote in the
first mail,
> kernel version: 4.10.0-34-generic
> aufs version: 4.x-rcN-20170206

Is it ubuntu zesty?
I got git://kernel.ubuntu.com/ubuntu/ubuntu-zesty.git, and found
Ubuntu-4.10.0-34.38 tag. Is this the kernel you are using?

Anyway I checked it out and found these commits.

3eef97 2017-08-23 UBUNTU: SAUCE: aufs: bugfix, for v4.10, copy-up on XFS branch
bd1592e 2017-08-23 UBUNTU: SAUCE: aufs: for v4.5, use vfs_clone_file_range() in 
copy-up
e14748e 2017-02-19 UBUNTU: SAUCE: Import aufs driver
0815cfd 2017-02-19 Revert "UBUNTU: SAUCE: Import aufs driver"

It means
- 0815cfd removed all aufs files.
- e14748e added all aufs files, and the commit log says it is a copy of
6c73f3b 2017-02-04 aufs4.x-rcN 20170206
  from aufs4-standalone.git repo.
- after half a year, they imported a bugfix.

Ok then, there shoule be no difference at all between zesty#e14748e and
aufs4#6c73f3b. But I found several diffs. Additionally those diffs are
releated to the mutex lock around your AB-BA problem!!
It is really enough to confuse me very much. But now I think I could get
it over.


J. R. Okajima

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[Eddie Horng]

--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot

Re: hung_task_timeout: mutex_lock in aufs

[sfjro--- via Aufs-users]

Hello Eddie,

Eddie Horng:
> I got hung to access to an aufs mount dir, dmesg shows mutex_lock call
> stack in aufs.
:::
> kernel version: 4.10.0-34-generic
> aufs version: 4.x-rcN-20170206

Hmm, your version is rather old, almost a year ago. But I don't think it
important.

> dmesg log:
:::
> [Tue Jan 16 16:02:22 2018] INFO: task ninja:18218 blocked for more than 120
> seconds.
:::
> [Tue Jan 16 16:02:22 2018]  mutex_lock+0x2f/0x40
> [Tue Jan 16 16:02:22 2018]  au_xino_delete_inode+0x18c/0x1e0 [aufs]
> [Tue Jan 16 16:02:22 2018]  au_iinfo_fin+0x163/0x1d0 [aufs]
> [Tue Jan 16 16:02:22 2018]  aufs_destroy_inode+0x47/0x50 [aufs]
> [Tue Jan 16 16:02:22 2018]  destroy_inode+0x3b/0x60
> [Tue Jan 16 16:02:22 2018]  evict+0x136/0x1a0
> [Tue Jan 16 16:02:22 2018]  iput+0x1b2/0x230
> [Tue Jan 16 16:02:22 2018]  do_unlinkat+0x12c/0x320
> [Tue Jan 16 16:02:22 2018]  SyS_unlink+0x16/0x20

So you have several proccesses which are all blocked in
+ au_iinfo_fin
  + au_xino_delete_inode
+ mutex_lock

Hmm, currently, I don't know what is wrong at all.

Explicitly au_xino_delete_inode() acquires an aufs internal mutex lock
to maintain the internal bitmap.
Also the function implicitiy acquires a mutex lock for the XINO file,
which should be located on your first writable branch /vol/upper.
These two mutexes are the major candidates I guess.

I am not sure which mutex lock causes the problem, and I'd suggest you
to try these.
- first, just for the confirmation, "cat /sys/fs/aufs/si_*/xi_path" and
  it should print /vol/upper/.aufs.xino.
- apply lockdep-debug.patch and enable CONFIG_LOCKDEP.
- rebuild your kernel and aufs module.
- reboot and test.
- when the problem happens, you can see the acquired locks in dmesg. So
  we can identify which mutex lock is problematic.


J. R. Okajima



--
Check out the vibrant tech community on one of the world's most
engaging tech sites, Slashdot.org! http://sdm.link/slashdot