evdev mutex inconsistent lock state

[Tixy (Jon Medhurst)]

I've been fairly regularly seeing "inconsistent lock state" backtraces when running Android on vexpress TC2. See attached log.

This looks like a problem with how the evdev driver uses a mutex.

[Tixy (Jon Medhurst) (tixy)]

This bug is caused by the Android patch called " Input: evdev - Add ioctl to block suspend while event queue is not empty."

This is broken because evdev_enable_suspend_block() has

 spin_lock_irq(&client->buffer_lock);
 wake_lock_init(&client->wake_lock, WAKE_LOCK_SUSPEND, client->name);
 [...]
 spin_unlock_irq(&client->buffer_lock);

which means that wake_lock_init() is called with interrupts disabled. However wake_lock_init() calls wakeup_source_add() which itself uses spinlocks like...

 spin_lock_irq(&events_lock);
 [...]
 spin_unlock_irq(&events_lock);

which assumes that it is called with interrupts enabled. As a consequence, the spin_unlock_irq() above unconditionally enables irqs which means the evdev code which called it is now holding the client->buffer_lock with interrupts enabled, opening up the opportunity for deadlock to occur if an interrupt happens for an event which then calls evdev_pass_event() and then waits on the same spinlock.

[Botao (botao-sun)]

For vexpress A9 board, observed on Linaro Jelly Bean image:

https://android-build.linaro.org/builds/~linaro-android/vexpress-jb-gcc47-armlt-tracking-open/#build=30

Please refer to attachment to get full boot log.

[John Stultz (jstultz)]

Per Tixy's debugging, I've generated a patch to use irqsave/restore when accessing the events_lock.
This seems to me to be the right fix, but I've sent it to the PM maintainer for comment before wider submission.

If this is right, we will need to make sure this gets backported to AOSPs common.git/android-3.4 and submitted to Gerrit.

[John Stultz (jstultz)]

Patch sent to lkml and pushed out via linaro-android-3.6-jstultz-rebase

Once the patch is merged upstream, I'll send it on to AOSP.

[Tixy (Jon Medhurst) (tixy)]

Patch "wakeup: Use irqsave/irqrestore for events_lock" applied to http://git.linaro.org/gitweb?p=people/jstultz/android.git;a=shortlog;h=refs/heads/linaro-android-3.6-jstultz-rebase

[Amit Khare (amit-khare)]

Observed with android vexpress JB build
https://android-build.linaro.org/builds/~linaro-android/vexpress-jb-gcc47-armlt-tracking-open/#build=37

LOGS:

[ 263.224205] CPU0
[ 263.231518] ----
[ 263.238827] lock(&(&client->buffer_lock)->rlock);
[ 263.253461] <Interrupt>
[ 263.261294] lock(&(&client->buffer_lock)->rlock);
[ 263.276449]
[ 263.276449] *** DEADLOCK ***
[ 263.276449]
[ 263.294192] 2 locks held by InputReader/2014:
[ 263.307237] #0: (&evdev->mutex){+.+...}, at: [<c03aadc4>] evdev_ioctl+0x2c/0x91c
[ 263.330005] #1: (&(&client->buffer_lock)->rlock){?.....}, at: [<c03aafe4>] evdev_ioctl+0x24c/0x91c
[ 263.357450]
[ 263.357450] stack backtrace:
[ 263.370533] [<c0015058>] (unwind_backtrace+0x0/0xf8) from [<c04fce78>] (print_usage_bug+0x248/0x2b0)
[ 263.397929] [<c04fce78>] (print_usage_bug+0x248/0x2b0) from [<c0071c70>] (mark_lock+0x2a0/0x67c)
[ 263.424276] [<c0071c70>] (mark_lock+0x2a0/0x67c) from [<c007468c>] (mark_held_locks+0x5c/0x124)
[ 263.450361] [<c007468c>] (mark_held_locks+0x5c/0x124) from [<c00747fc>] (trace_hardirqs_on_caller+0xa8/0x190)
[ 263.480096] [<c00747fc>] (trace_hardirqs_on_caller+0xa8/0x190) from [<c05052e4>] (_raw_spin_unlock_irq+0x24/0x2c)
[ 263.510875] [<c05052e4>] (_raw_spin_unlock_irq+0x24/0x2c) from [<c03aaff8>] (evdev_ioctl+0x260/0x91c)
[ 263.538529] [<c03aaff8>] (evdev_ioctl+0x260/0x91c) from [<c00f4678>] (do_vfs_ioctl+0x80/0x538)
[ 263.564352] [<c00f4678>] (do_vfs_ioctl+0x80/0x538) from [<c00f4b64>] (sys_ioctl+0x34/0x60)
[ 263.589133] [<c00f4b64>] (sys_ioctl+0x34/0x60) from [<c000e000>] (ret_fast_syscall+0x0/0x3c)
[ 362.131513] init: sys_prop: permission denied uid:1003 name:service.bootanim.exit
[ 476.986679] mmcblk0: error -5 transferring data, sector 617064, nr 24, cmd response 0x900, card status 0xb00
[ 477.016346] mmcblk0: retrying using single block transfer
[ 484.922577] mmcblk0: error -5 transferring data, sector 1979938, nr 30, cmd response 0x900, card status 0xc00
[ 484.952583] mmcblk0: retrying using single block transfer
[ 486.646280] mmcblk0: error -5 transferring data, sector 624360, nr 8, cmd response 0x900, card status 0xb00
[ 486.675675] mmcblk0: retrying using single block transfer

[John Stultz (jstultz)]

Amit: Has build37 included the fix above?

[Amit Khare (amit-khare)]

John: Looking at the logs it seems the fix is not included with this build. I see similar out put on build 37 as in comment #3 by Botao

[John Stultz (jstultz)]

Colin Cross just pulled this fix into AOSP for Android's offical 3.4 tree.

[Amit Khare (amit-khare)]

Observed with android vexpress JB build
https://android-build.linaro.org/builds/~linaro-android/vexpress-jb-gcc47-armlt-tracking-open/#build=42

I dont see the DEADLOCK issue now but lot of sdcard related issues are there.

LOGS:

[ 21.851704] mmcblk0: retrying using single block transfer
[ 22.574259] init: cannot find '/system/bin/rild', disabling 'ril-daemon'
[ 22.686519] usb 1-1.2: new full-speed USB device number 47 using isp1760
[ 22.706855] mmcblk0: error -5 transferring data, sector 782368, nr 24, cmd response 0x900, card status 0xb00
[ 22.736382] mmcblk0: retrying using single block transfer
[ 22.786593] usb 1-1.2: device descriptor read/64, error -32
[ 22.986556] usb 1-1.2: device descriptor read/64, error -32
[ 23.003532] mmcblk0: error -5 transferring data, sector 754920, nr 24, cmd response 0x900, card status 0xb00
[ 23.033079] mmcblk0: retrying using single block transfer
[ 23.186641] usb 1-1.2: new full-speed USB device number 48 using isp1760
[ 23.207079] mmcblk0: error -5 transferring data, sector 751520, nr 24, cmd response 0x900, card status 0xb00
[ 23.236649] mmcblk0: retrying using single block transfer
[ 23.326558] usb 1-1.2: device descriptor read/64, error -32

[Botao (botao-sun)]

@Amit, those SD card errors are expected. This bug is used for tracking that "DEADLOCK" issue and now it has been solved.