Bug 280311

I'm not exactly clear on what lockdep is complaining about, but I think it's
lock ordering. It had already seen lockd take the f_mutex then the
nlm_host_mutex, but apparently the codepath above is now doing this in the
reverse order.

Created attachment 196301 [details]
kernel log

As an additional data point, I am seeing the same problem with 2.6.22.5-49.fc6debug:

=======================================================
[ INFO: possible circular locking dependency detected ]
2.6.22.5-49.fc6debug #1
-------------------------------------------------------
lockd/3100 is trying to acquire lock:
 (&file->f_mutex){--..}, at: [<c0646a8e>] mutex_lock+0x21/0x24

but task is already holding lock:
 (nlm_host_mutex){--..}, at: [<c0646a8e>] mutex_lock+0x21/0x24

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (nlm_host_mutex){--..}:
       [<c0446a92>] __lock_acquire+0x9ea/0xb75
       [<c044700f>] lock_acquire+0x56/0x6f
       [<c06468f6>] __mutex_lock_slowpath+0xf7/0x26e
       [<c0646a8e>] mutex_lock+0x21/0x24
       [<f8ee491c>] nlm_lookup_host+0x8f/0x2d9 [lockd]
       [<f8ee4b96>] nlmsvc_lookup_host+0x30/0x37 [lockd]
       [<f8ee6393>] nlmsvc_lock+0xc1/0x2f6 [lockd]
       [<f8ee9a25>] nlm4svc_proc_lock+0x8b/0xd3 [lockd]
       [<f8f4abc5>] svc_process+0x336/0x66d [sunrpc]
       [<f8ee5363>] lockd+0x14c/0x225 [lockd]
       [<c0405c8f>] kernel_thread_helper+0x7/0x10
       [<ffffffff>] 0xffffffff

-> #0 (&file->f_mutex){--..}:
       [<c0446976>] __lock_acquire+0x8ce/0xb75
       [<c044700f>] lock_acquire+0x56/0x6f
       [<c06468f6>] __mutex_lock_slowpath+0xf7/0x26e
       [<c0646a8e>] mutex_lock+0x21/0x24
       [<f8ee6120>] nlmsvc_traverse_blocks+0x22/0x8c [lockd]
       [<f8ee7418>] nlm_traverse_files+0x1b1/0x20c [lockd]
       [<f8ee74f5>] nlmsvc_mark_resources+0x27/0x29 [lockd]
       [<f8ee446c>] nlm_gc_hosts+0x49/0x19b [lockd]
       [<f8ee4933>] nlm_lookup_host+0xa6/0x2d9 [lockd]
       [<f8ee4b96>] nlmsvc_lookup_host+0x30/0x37 [lockd]
       [<f8ee9570>] nlm4svc_retrieve_args+0x38/0xb6 [lockd]
       [<f8ee99f9>] nlm4svc_proc_lock+0x5f/0xd3 [lockd]
       [<f8f4abc5>] svc_process+0x336/0x66d [sunrpc]
       [<f8ee5363>] lockd+0x14c/0x225 [lockd]
       [<c0405c8f>] kernel_thread_helper+0x7/0x10
       [<ffffffff>] 0xffffffff

other info that might help us debug this:

1 lock held by lockd/3100:
 #0:  (nlm_host_mutex){--..}, at: [<c0646a8e>] mutex_lock+0x21/0x24

stack backtrace:
 [<c04061ac>] show_trace_log_lvl+0x1a/0x2f
 [<c0406c30>] show_trace+0x12/0x14
 [<c0406c89>] dump_stack+0x16/0x18
 [<c04451c3>] print_circular_bug_tail+0x5f/0x68
 [<c0446976>] __lock_acquire+0x8ce/0xb75
 [<c044700f>] lock_acquire+0x56/0x6f
 [<c06468f6>] __mutex_lock_slowpath+0xf7/0x26e
 [<c0646a8e>] mutex_lock+0x21/0x24
 [<f8ee6120>] nlmsvc_traverse_blocks+0x22/0x8c [lockd]
 [<f8ee7418>] nlm_traverse_files+0x1b1/0x20c [lockd]
 [<f8ee74f5>] nlmsvc_mark_resources+0x27/0x29 [lockd]
 [<f8ee446c>] nlm_gc_hosts+0x49/0x19b [lockd]
 [<f8ee4933>] nlm_lookup_host+0xa6/0x2d9 [lockd]
 [<f8ee4b96>] nlmsvc_lookup_host+0x30/0x37 [lockd]
 [<f8ee9570>] nlm4svc_retrieve_args+0x38/0xb6 [lockd]
 [<f8ee99f9>] nlm4svc_proc_lock+0x5f/0xd3 [lockd]
 [<f8f4abc5>] svc_process+0x336/0x66d [sunrpc]
 [<f8ee5363>] lockd+0x14c/0x225 [lockd]
 [<c0405c8f>] kernel_thread_helper+0x7/0x10
 =======================

Detlev,
  Did you happen to notice whether lockd was hung after seeing this warning?
Unfortunately I've not been able to reproduce this since (though I haven't tried
too hard)...

After asking someone more knowledgeable about lockdep, I think the issue is that
the kernel thinks there is a problem with lock ordering. The only takers of
these locks seem to be lockd though, so ordering shouldn't really be much of an
issue. From the stack traces above, the 

Supposedly, lockdep can get this wrong sometimes...maybe this is one of those cases?

I'd be less inclined to think so if lockd was really hung after these messages
popped...

Jeff,
lockd did not hang after the message.  In fact it is still running nicely.

From what I understand of lockdep, it warns us that one codepath took the 2
locks already in a different order than what is currently tried - so it _may_
happen that if both these codepaths should ever run concurrently with just the
right timing, they deadlock.

So even if the lockd on my machine is still running (Pentium IV, so 2 CPUs),
that is not really a proof that we have a false positive - the kernel doesn't
even use PREEMPT so the conditions may actually be very friendly to that
problem.  But CONFIG_PREEMPT and more CPUs could possibly provoke the error
quickly.

Pondering some more about the problem I cannot understand how this can be
only harmless.  Maybe it is neccessary to order the locks on levels (maybe
even introduce "an upper" level) and teach lockdep about that usage (like
described in Documentation/lockdep-design.txt) but unfortunately I won't be
able to do that :(

Thanks for the confirmation. That was my interpretation too.

I think I might see what lockdep is complaining about (well, at least one
possible ordering violation):

First call chain (more or less the one in the stack traces above):

nlm4svc_proc_lock
   nlm4svc_retrieve_args
      nlmsvc_lookup_host
         nlm_lookup_host   (nlm_host_mutex is taken)
             nlm_gc_hosts
                nlmsvc_mark_resources
                   nlm_traverse_files
                      nlm_inspect_file
                         nlmsvc_traverse_blocks (file->f_mutex is taken)


...but later...

nlm4svc_proc_lock
   nlmsvc_lock    (file->f_mutex is taken)
      nlmsvc_create_block
         nlmsvc_lookup_host
            nlm_lookup_host (nlm_host_mutex is taken)
      

...so there does seem to be some ordering violation with this. It's not clear to
me that any of these functions are called outside of lockd however.

A potential fix might be to rejigger nlm_gc_hosts() such that we don't need to
hold the nlm_host_mutex when nlmsvc_mark_resources() is called, but I'd welcome
suggestions on this :-)

Created attachment 202831 [details]
NLM: Fix a circular lock dependency in lockd

The problem is that the garbage collector for the 'host' structures
nlm_gc_hosts(), holds nlm_host_mutex while calling down to
nlmsvc_mark_resources, which, eventually takes the file->f_mutex.

We cannot therefore call nlmsvc_lookup_host() from within
nlmsvc_create_block, since the caller will already hold file->f_mutex, so
the attempt to grab nlm_host_mutex may deadlock.

Fix the problem by calling nlmsvc_lookup_host() outside the file->f_mutex.

Created attachment 203001 [details]
reproducer program

I've been able to reproduce this more or less at will by running this program
against the same file on the client and server. Eventually the lockdep warnings
pop.

Going to test Trond's patch now and see if it helps...

Patch seems to correct the problem. Closing this with a resolution of UPSTREAM.