Re: 2.6.17-rc5-mm3: bad unlock ordering (reiser4?)

Barry K. Nathan
2006-06-05T09:00:24Z

On 6/5/06, Ingo Molnar <mingo@elte.hu> wrote:
>
> * Barry K. Nathan <barryn@pobox.com> wrote:
[snip]
> > So, does that mean the plan is to annotate/tweak things in order to
> > shut up *each and every* false positive in the kernel?
>
> yes. Note that for the many reasons i outlined before they are only
> "half false positives" - i.e. they are potentially dangerous constructs
> and they are potentially inefficient - hence we _want to_ document them
> in the code, to increase the cleanliness of the kernel. A pure "false
> positive" would be a totally valid and perfect locking construct being
> flagged by the lock validator.
>
> nor do these warnings really hurt anyone. Lockdep prints info and then
> shuts up - the system continues to work.

Ok, thanks for explaining that.

> > Anyway, I tried your patch and I got this:
>
> please try the addon patch below.

I don't know if you saw this comment on the lock validator article at LWN?

---begin quote---
The kernel lock validator
Posted May 31, 2006 9:35 UTC (Wed) by subscriber nix [Link]

... and now reiser4 turns up with a tree of locks where each rank may
be taken within the rank above safely, but where there are a
potentially unbounded number of ranks...
---end quote---

I have no idea if that's actually the case, but if it is, it might be relevant.

Anyway, I have a new, more scary-looking lockdep warning:

http://members.cox.net/barrykn/linux/trace/dmesg.reiser4-4
http://members.cox.net/barrykn/linux/trace/latency_trace_reiser4-4.bz2

[ 316.680616] ( smbd-824 |#0): new 239822061 us user-latency.
[ 316.680805] stopped custom tracer.
[ 316.680951]
[ 316.680964] =====================================================
[ 316.681241] [ BUG: possible circular locking deadlock detected! ]
[ 316.681412] -----------------------------------------------------
[ 316.681575] smbd/824 is trying to acquire lock:
[ 316.681727] (&txnh->hlock){--..}, at: [<e09a884a>]
txn_end+0x3f9/0x47c [reiser4]
[ 316.682366]
[ 316.682379] but task is already holding lock:
[ 316.682629] (&atom->alock){--..}, at: [<e09a78da>]
txnh_get_atom+0x23/0x85 [reiser4]
[ 316.683192]
[ 316.683206] which lock already depends on the new lock,
[ 316.683472] which could lead to circular deadlocks!
[ 316.683633]
[ 316.683648] the existing dependency chain (in reverse order) is:
[ 316.683922]
[ 316.683936] -> #1 (&atom->alock){--..}:
[ 316.684392] [<c012f30f>] lockdep_acquire+0x67/0x7f
[ 316.685084] [<c029b67f>] _spin_lock+0x1d/0x2b
[ 316.685772] [<e09a7c0c>] try_capture+0x2d0/0x9cb [reiser4]
[ 316.686514] [<e09a214d>] longterm_lock_znode+0x2fc/0x415 [reiser4]
[ 316.687245] [<e09af884>] coord_by_handle+0x142/0xb76 [reiser4]
[ 316.687982] [<e09b03cc>] coord_by_key+0x55/0x5a [reiser4]
[ 316.688714] [<e09a3ca5>] insert_by_key+0x31/0x5c [reiser4]
[ 316.689483] [<e09bb77d>]
write_sd_by_inode_common+0x117/0x502 [reiser4]
[ 316.690340] [<e09bbb95>] create_object_common+0x2d/0x37 [reiser4]
[ 316.691092] [<e09b8f57>] create_vfs_object+0x376/0x551 [reiser4]
[ 316.691841] [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[ 316.692581] [<c0167a6e>] vfs_create+0x67/0xad
[ 316.693259] [<c016a832>] open_namei+0x19b/0x6cd
[ 316.693936] [<c0158d64>] do_filp_open+0x2b/0x42
[ 316.694621] [<c0158ddc>] do_sys_open+0x61/0xef
[ 316.695276] [<c0158e9d>] sys_open+0x18/0x1a
[ 316.695934] [<c029b8cc>] syscall_call+0x7/0xb
[ 316.696629]
[ 316.696643] -> #0 (&txnh->hlock){--..}:
[ 316.697087] [<c012f30f>] lockdep_acquire+0x67/0x7f
[ 316.697781] [<c029b67f>] _spin_lock+0x1d/0x2b
[ 316.698451] [<e09a884a>] txn_end+0x3f9/0x47c [reiser4]
[ 316.699242] [<e09a443c>] reiser4_exit_context+0xb2/0x125 [reiser4]
[ 316.699981] [<e09b90f2>] create_vfs_object+0x511/0x551 [reiser4]
[ 316.700729] [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[ 316.701467] [<c0167a6e>] vfs_create+0x67/0xad
[ 316.702142] [<c016a832>] open_namei+0x19b/0x6cd
[ 316.702823] [<c0158d64>] do_filp_open+0x2b/0x42
[ 316.703493] [<c0158ddc>] do_sys_open+0x61/0xef
[ 316.704159] [<c0158e9d>] sys_open+0x18/0x1a
[ 316.704831] [<c029b8cc>] syscall_call+0x7/0xb
[ 316.705518]
[ 316.705532] other info that might help us debug this:
[ 316.705566]
[ 316.705936] 2 locks held by smbd/824:
[ 316.706085] #0: (&inode->i_mutex){--..}, at: [<c0299d58>]
mutex_lock+0xd/0xf
[ 316.706654] #1: (&atom->alock){--..}, at: [<e09a78da>]
txnh_get_atom+0x23/0x85 [reiser4]
[ 316.707335]
[ 316.707349] stack backtrace:
[ 316.709560] [<c01032ab>] show_trace_log_lvl+0x64/0x125
[ 316.710003] [<c01038bd>] show_trace+0x1b/0x20
[ 316.710421] [<c0103914>] dump_stack+0x1f/0x24
[ 316.710842] [<c012e400>] print_circular_bug_tail+0x5d/0x69
[ 316.712546] [<c012eca2>] __lockdep_acquire+0x896/0xa91
[ 316.714438] [<c012f30f>] lockdep_acquire+0x67/0x7f
[ 316.716133] [<c029b67f>] _spin_lock+0x1d/0x2b
[ 316.717929] [<e09a884a>] txn_end+0x3f9/0x47c [reiser4]
[ 316.718768] [<e09a443c>] reiser4_exit_context+0xb2/0x125 [reiser4]
[ 316.719319] [<e09b90f2>] create_vfs_object+0x511/0x551 [reiser4]
[ 316.720536] [<e09b91bb>] create_common+0x44/0x4b [reiser4]
[ 316.721610] [<c0167a6e>] vfs_create+0x67/0xad
[ 316.724954] [<c016a832>] open_namei+0x19b/0x6cd
[ 316.728125] [<c0158d64>] do_filp_open+0x2b/0x42
[ 316.730886] [<c0158ddc>] do_sys_open+0x61/0xef
[ 316.733473] [<c0158e9d>] sys_open+0x18/0x1a
[ 316.736245] [<c029b8cc>] syscall_call+0x7/0xb

--
-Barry K. Nathan <barryn@pobox.com>