Re: drm_vm.c:drm_mmap: possible circular locking dependency detected

[ebiederm@xmission.com (Eric W. Biederman)]

Dmitry Torokhov <dmitry.torokhov@gmail.com> writes:

> On Sun, Jan 03, 2010 at 09:32:06AM +0900, Tejun Heo wrote:
>> On 01/03/2010 06:49 AM, Eric W. Biederman wrote:
>> 
>> > For the moment I have generated a patch that does the lockdep
>> > annotations, and I have found that a simple:
>> > 
>> >    find /sys -type f | xargs cat {} > /dev/null
>> > 
>> > trivially generates lockdep warnings.  In particular:
>> 
>> (cc'ing Dmitry, Hi!)
>
> Hi Tejun! ;)
>
>> 
>> > [  165.049042] 
>> > [  165.049044] =======================================================
>> > [  165.052761] [ INFO: possible circular locking dependency detected ]
>> > [  165.052761] 2.6.33-rc2x86_64 #3
>> > [  165.052761] -------------------------------------------------------
>> > [  165.052761] cat/5026 is trying to acquire lock:
>> > [  165.052761]  (&serio->drv_mutex){+.+.+.}, at: [<ffffffff8132ecaa>] atkbd_attr_show_helper+0x28/0x6e
>> > [  165.052761] 
>> > [  165.052761] but task is already holding lock:
>> > [  165.089443]  (s_active){++++.+}, at: [<ffffffff810e84dd>] sysfs_get_active_two+0x2c/0x43
>> > [  165.089443] 
>> > [  165.089443] which lock already depends on the new lock.
>> > [  165.089443] 
>> > [  165.089443] 
>> > [  165.089443] the existing dependency chain (in reverse order) is:
>> > [  165.089443] 
>> > [  165.089443] -> #1 (s_active){++++.+}:
>> > [  165.089443]        [<ffffffff81054956>] validate_chain+0xa25/0xd1d
>> > [  165.089443]        [<ffffffff810553d3>] __lock_acquire+0x785/0x7dc
>> > [  165.089443]        [<ffffffff81056112>] lock_acquire+0x5a/0x74
>> > [  165.089443]        [<ffffffff810e8202>] sysfs_addrm_finish+0xba/0x125
>> > [  165.089443]        [<ffffffff810e68b0>] sysfs_hash_and_remove+0x4f/0x6b
>> > [  165.089443]        [<ffffffff810e94cf>] remove_files+0x1f/0x2c
>> > [  165.089443]        [<ffffffff810e9561>] sysfs_remove_group+0x85/0xb4
>> > [  165.089443]        [<ffffffff81331f0f>] psmouse_disconnect+0x33/0x147
>> > [  165.089443]        [<ffffffff8132687b>] serio_disconnect_driver+0x2d/0x3a
>> > [  165.089443]        [<ffffffff81326898>] serio_driver_remove+0x10/0x14
>> > [  165.089443]        [<ffffffff812077f0>] __device_release_driver+0x67/0xb0
>> > [  165.089443]        [<ffffffff81207857>] device_release_driver+0x1e/0x2b
>> > [  165.089443]        [<ffffffff81326e68>] serio_disconnect_port+0x60/0x69
>> > [  165.089443]        [<ffffffff8132757a>] serio_thread+0x170/0x34a
>> > [  165.089443]        [<ffffffff810470e7>] kthread+0x7d/0x85
>> > [  165.089443]        [<ffffffff81002cd4>] kernel_thread_helper+0x4/0x10
>> > [  165.089443] 
>> > [  165.089443] -> #0 (&serio->drv_mutex){+.+.+.}:
>> > [  165.089443]        [<ffffffff81054642>] validate_chain+0x711/0xd1d
>> > [  165.089443]        [<ffffffff810553d3>] __lock_acquire+0x785/0x7dc
>> > [  165.089443]        [<ffffffff81056112>] lock_acquire+0x5a/0x74
>> > [  165.089443]        [<ffffffff814378ed>] mutex_lock_interruptible_nested+0x4a/0x307
>> > [  165.089443]        [<ffffffff8132ecaa>] atkbd_attr_show_helper+0x28/0x6e
>> > [  165.089443]        [<ffffffff8132ed81>] atkbd_do_show_extra+0x13/0x15
>> > [  165.089443]        [<ffffffff812049b6>] dev_attr_show+0x20/0x43
>> > [  165.089443]        [<ffffffff810e71db>] sysfs_read_file+0xba/0x145
>> > [  165.089443]        [<ffffffff8109f507>] vfs_read+0xab/0x147
>> > [  165.089443]        [<ffffffff8109f85c>] sys_read+0x47/0x70
>> > [  165.089443]        [<ffffffff81001f2b>] system_call_fastpath+0x16/0x1b
>> > [  165.089443] 
>> > [  165.089443] other info that might help us debug this:
>> > [  165.089443] 
>> > [  165.089443] 3 locks held by cat/5026:
>> > [  165.089443]  #0:  (&buffer->mutex){+.+.+.}, at: [<ffffffff810e715a>] sysfs_read_file+0x39/0x145
>> > [  165.089443]  #1:  (s_active){++++.+}, at: [<ffffffff810e84d0>] sysfs_get_active_two+0x1f/0x43
>> > [  165.089443]  #2:  (s_active){++++.+}, at: [<ffffffff810e84dd>] sysfs_get_active_two+0x2c/0x43
>> > [  165.089443] 
>> > [  165.089443] stack backtrace:
>> > [  165.089443] Pid: 5026, comm: cat Not tainted 2.6.33-rc2x86_64 #3
>> > [  165.089443] Call Trace:
>> > [  165.089443]  [<ffffffff810538f3>] print_circular_bug+0xb3/0xc1
>> > [  165.089443]  [<ffffffff81054642>] validate_chain+0x711/0xd1d
>> > [  165.089443]  [<ffffffff81052fb6>] ? trace_hardirqs_on_caller+0x10b/0x12f
>> > [  165.089443]  [<ffffffff810553d3>] __lock_acquire+0x785/0x7dc
>> > [  165.089443]  [<ffffffff8132ecaa>] ? atkbd_attr_show_helper+0x28/0x6e
>> > [  165.089443]  [<ffffffff81056112>] lock_acquire+0x5a/0x74
>> > [  165.089443]  [<ffffffff8132ecaa>] ? atkbd_attr_show_helper+0x28/0x6e
>> > [  165.089443]  [<ffffffff814378ed>] mutex_lock_interruptible_nested+0x4a/0x307
>> > [  165.089443]  [<ffffffff8132ecaa>] ? atkbd_attr_show_helper+0x28/0x6e
>> > [  165.089443]  [<ffffffff8132ee41>] ? atkbd_show_extra+0x0/0x28
>> > [  165.089443]  [<ffffffff8132ecaa>] atkbd_attr_show_helper+0x28/0x6e
>> > [  165.089443]  [<ffffffff8132ed81>] atkbd_do_show_extra+0x13/0x15
>> > [  165.089443]  [<ffffffff812049b6>] dev_attr_show+0x20/0x43
>> > [  165.089443]  [<ffffffff810e71db>] sysfs_read_file+0xba/0x145
>> > [  165.089443]  [<ffffffff8109f507>] vfs_read+0xab/0x147
>> > [  165.089443]  [<ffffffff8109f85c>] sys_read+0x47/0x70
>> > [  165.089443]  [<ffffffff81001f2b>] system_call_fastpath+0x16/0x1b
>> > 
>> > Suggestions on how to sort out this other set of issues are welcome.
>> 
>> Ummm... read of an input sysfs node can trigger
>
> Read? I checked and I do not see where read would cause disconnect.
> Also, disconnect only involves unbinding driver from the port, not the
> destruction of the port itself (children may be destroyed but they have
> different locks).
>
>> serio_disconnect_port() under serio->drv_mutex, which unfortunately
>> would need to wait for completion of in-progress sysfs ops thus
>> creating possibility for AB-BA deadlock. 
>
> I think that we are dealing with different drv->mutex instances here.
>
>> Dmitry, is it possible to
>> make serio_disconnect_port() asynchronous from the sysfs ops (ie. put
>> it in a work or something)?
>
> I am not sure it is needed. Also in the trace presented
> serio_disconnect_port() is called from kseriod which certainly does not
> access sysfs...
>
> Overall I am not concerned about lockdep bitching about serio because it
> still bitches if you simply reload psmouse on a box with Synaptics with a
> pass-through port even though there are nested annotations and it is
> silent first time around.

This is a new lockdep annotation, and looking into it this appears to
be a true possible deadlock in the serio/sysfs interactions.

We have serio_pin_driver() called from all of the sysfs attributes
which does:
   mutex_lock(&serio->drv_mutex);

We have serio_disconnect_driver() called on an unplug which does:
   mutex_lock(&serio->drv_mutex);

The deadlock potential is if someone reads say the psmouse rate
sysfs file while the mouse is being unplugged.  There is a race
such that we can have:

						  sysfs_read_file()
                                                    fill_read_buffer()
						       sysfs_get_active_two()
							 psmouse_attr_show_helper()
                                        		   serio_pin_driver()
serio_disconnect_driver()		
  mutex_lock(&serio->drv_mutex);		
				<----------------->	   mutex_lock(&serio_drv_mutex);
    psmouse_disconnect()
      sysfs_remove_group(... psmouse_attr_group);
	....
	sysfs_deactivate(); 
	  wait_for_completion();


So it is unlikely but possible to deadlock by accessing a serio
attribute of a serio device that is being removed.

What to do about it is another question.   It has just recently come to my
attention that we have more events like this

> Out of curiosity, do yo uknow what caused psmouse disconnect and what
> kind of mouse is in the box?

It is a simple ps2mouse connected through a kvm, and the kvm was not
switched to the machine in question during the run.

I am trying to wrap my head around what to do with this sysfs_deactivate
deadlock scenario, (other drivers also hold unfortunate locks over the
removal of sysfs files,  and it just happens that the ps2mouse case was the first
one I reproduced), and it was interesting because I had not seen it before.

Eric