Deadlock in gpiolib

Deadlock in gpiolib

[Uwe Kleine-König]

Hello,

Just by doing

	echo $gpio > /sys/class/gpio/export
	echo in > /sys/class/gpio/gpio$gpio/direction
	echo $gpio > /sys/class/gpio/unexport

I hit the following lockdep warning:

[   46.300000] =======================================================
[   46.300000] [ INFO: possible circular locking dependency detected ]
[   46.300000] 2.6.38-rc5-00308-g92942b4 #325
[   46.300000] -------------------------------------------------------
[   46.300000] sh/88 is trying to acquire lock:
[   46.300000]  (sysfs_lock){+.+.+.}, at: [<c0197e6c>] gpio_direction_store+0x20/0xf0
[   46.300000] 
[   46.300000] but task is already holding lock:
[   46.300000]  (s_active#7){++++.+}, at: [<c0120c00>] sysfs_write_file+0xe4/0x140
[   46.300000] 
[   46.300000] which lock already depends on the new lock.
[   46.300000] 
[   46.300000] 
[   46.300000] the existing dependency chain (in reverse order) is:
[   46.300000] 
[   46.300000] -> #1 (s_active#7){++++.+}:
[   46.300000]        [<c00706b0>] validate_chain+0x520/0x698
[   46.300000]        [<c007104c>] __lock_acquire+0x824/0x900
[   46.300000]        [<c0071200>] lock_acquire+0xd8/0xf8
[   46.300000]        [<c01218d8>] sysfs_deactivate+0xbc/0x110
[   46.300000]        [<c01224b4>] sysfs_addrm_finish+0x28/0x70
[   46.300000]        [<c01225a8>] sysfs_remove_dir+0x70/0x84
[   46.300000]        [<c0189640>] kobject_del+0x10/0x38
[   46.300000]        [<c01b8f44>] device_del+0x188/0x1a0
[   46.300000]        [<c01b8f68>] device_unregister+0xc/0x18
[   46.300000]        [<c01974e0>] gpio_unexport+0x98/0xdc
[   46.300000]        [<c0197568>] gpio_free+0x44/0x15c
[   46.300000]        [<c01976e8>] unexport_store+0x68/0x9c
[   46.300000]        [<c01bbdd0>] class_attr_store+0x20/0x28
[   46.300000]        [<c0120c24>] sysfs_write_file+0x108/0x140
[   46.300000]        [<c00d3d68>] vfs_write+0xac/0x188
[   46.300000]        [<c00d3efc>] sys_write+0x40/0x6c
[   46.300000]        [<c00289a0>] ret_fast_syscall+0x0/0x38
[   46.300000] 
[   46.300000] -> #0 (sysfs_lock){+.+.+.}:
[   46.300000]        [<c006fc18>] check_prev_add+0x118/0x690
[   46.300000]        [<c00706b0>] validate_chain+0x520/0x698
[   46.300000]        [<c007104c>] __lock_acquire+0x824/0x900
[   46.300000]        [<c0071200>] lock_acquire+0xd8/0xf8
[   46.300000]        [<c026b69c>] mutex_lock_nested+0x58/0x2a8
[   46.300000]        [<c0197e6c>] gpio_direction_store+0x20/0xf0
[   46.300000]        [<c01b7bc4>] dev_attr_store+0x20/0x28
[   46.300000]        [<c0120c24>] sysfs_write_file+0x108/0x140
[   46.300000]        [<c00d3d68>] vfs_write+0xac/0x188
[   46.300000]        [<c00d3efc>] sys_write+0x40/0x6c
[   46.300000]        [<c00289a0>] ret_fast_syscall+0x0/0x38
[   46.300000] 
[   46.300000] other info that might help us debug this:
[   46.300000] 
[   46.300000] 2 locks held by sh/88:
[   46.300000]  #0:  (&buffer->mutex){+.+.+.}, at: [<c0120b44>] sysfs_write_file+0x28/0x140
[   46.300000]  #1:  (s_active#7){++++.+}, at: [<c0120c00>] sysfs_write_file+0xe4/0x140
[   46.300000] 
[   46.300000] stack backtrace:
[   46.300000] [<c002e2e4>] (unwind_backtrace+0x0/0xec) from [<c006f55c>] (print_circular_bug+0xcc/0xe8)
[   46.300000] [<c006f55c>] (print_circular_bug+0xcc/0xe8) from [<c006fc18>] (check_prev_add+0x118/0x690)
[   46.300000] [<c006fc18>] (check_prev_add+0x118/0x690) from [<c00706b0>] (validate_chain+0x520/0x698)
[   46.300000] [<c00706b0>] (validate_chain+0x520/0x698) from [<c007104c>] (__lock_acquire+0x824/0x900)
[   46.300000] [<c007104c>] (__lock_acquire+0x824/0x900) from [<c0071200>] (lock_acquire+0xd8/0xf8)
[   46.300000] [<c0071200>] (lock_acquire+0xd8/0xf8) from [<c026b69c>] (mutex_lock_nested+0x58/0x2a8)
[   46.300000] [<c026b69c>] (mutex_lock_nested+0x58/0x2a8) from [<c0197e6c>] (gpio_direction_store+0x20/0xf0)
[   46.300000] [<c0197e6c>] (gpio_direction_store+0x20/0xf0) from [<c01b7bc4>] (dev_attr_store+0x20/0x28)
[   46.300000] [<c01b7bc4>] (dev_attr_store+0x20/0x28) from [<c0120c24>] (sysfs_write_file+0x108/0x140)
[   46.300000] [<c0120c24>] (sysfs_write_file+0x108/0x140) from [<c00d3d68>] (vfs_write+0xac/0x188)
[   46.300000] [<c00d3d68>] (vfs_write+0xac/0x188) from [<c00d3efc>] (sys_write+0x40/0x6c)
[   46.300000] [<c00d3efc>] (sys_write+0x40/0x6c) from [<c00289a0>] (ret_fast_syscall+0x0/0x38)

I tried to wrap my head around all that sysfs stuff and the implied
locking, but I failed.

Best regards
Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |

Re: Deadlock in gpiolib

[Thomas Gleixner]

[-- Attachment #1: Type: TEXT/PLAIN, Size: 2525 bytes --]

On Fri, 18 Feb 2011, Uwe Kleine-König wrote:

Brilliant move to not CC the ones who explained you in detail why this
lockdep splat triggers and why it can lead to a real deadlock.

<SNIP>
 
> I tried to wrap my head around all that sysfs stuff and the implied
> locking, but I failed.

You did not even think about providing the information about the
already decoded problem and instead you post your findings as
something completely new and unexplainable.

Dude, that sucks and I'm seriously grumpy about that. As you are too
tired, I sat down and retrieved from the IRC logs what avoids people
to twist their brain around that clusterf*ck over and over.

<peterz>  
	 well, if you, like mentioned, assume sysfs_get/put_active() is a lock,
	 then what it did is: sysfs_get_active_lock(); mutex_lock(sysfs_lock);
	 vs mutex_lock(sysfs_lock); sysfs_deactivate();
	 where, sysfs_deactivate() can be considered to also want a ref
	 which gets you AB-BA

<tglx>
	export does
	lock(sysfs_lock) -> create sysfs entries 
	read does -> "read-lock(sysfs-entry)" -> lock(sysfs_lock)
	unexport does
	lock(sysfs_lock) -> remove sysfs entries, which needs to read_lock them 
	and looking at the implementation it can actually deadlock
	assume one reader vs one unexporter
	cat gpio74/value is in progress while on the other side you do echo 74 >unexport
	then the unexport will hang in wait for completion
	while the reader is waiting for sysfs lock in gpio

There is more info in those logs, but i'm too tired to extract it, so
here is my tentative conclusion in clear text:

sysfs_lock in gpio is only useful to serialize export
vs. unexport. The comment above the lock declaration 

/* lock protects against unexport_gpio() being called while
 * sysfs files are active.
 */

is stupid.

The only real concern is a concurrent instantiation of that sysfs
export vs. a teardown. That might be eventually be handled by the
EXPORT bit in the flags of that gpio chip, but I have not had time to
look at it closely.

Taking the gpio:sysfs_lock inside of the particular read/write
functions is pointless. If sysfs is not preventing the teardown of
that entry while access in progress then sysfs needs fixing.

AFAICT the refcounting in sysfs (which leads to that lockdep splat)
does the right thing, so taking gpiolib:sysfs_lock inside those
read/write functions which are associated with an exported gpio is
simply wrong.

I leave the deeper analysis to the gpio crowd and sysfs experts, but I
would be surprised if I'm wrong.

Thanks,

	tglx

Re: Deadlock in gpiolib

[Uwe Kleine-König]

Hello Thomas,

On Sat, Feb 19, 2011 at 01:27:04AM +0100, Thomas Gleixner wrote:
> On Fri, 18 Feb 2011, Uwe Kleine-König wrote:
> > I tried to wrap my head around all that sysfs stuff and the implied
> > locking, but I failed.
> 
> You did not even think about providing the information about the
> already decoded problem and instead you post your findings as
> something completely new and unexplainable.
Sorry, really wasn't a very clever and thanks for providing the
necessary details.

Uwe

-- 
Pengutronix e.K.                           | Uwe Kleine-König            |
Industrial Linux Solutions                 | http://www.pengutronix.de/  |