2.6.31-rc3: circular locking: option_resume / usb_extern,al_resume_device

[Thiemo Nagel]

The following happened on a suspend-resume cycle with
2.6.31-rc3 on an Eee PC 1000HGO.  So far I've only observed it once.
Kernel config and bootup dmesg output is attached.

If somebody is interested in further info, just ask...

Kind regards,

Thiemo

[ 3333.197562] usb 5-6: unlink qh2-0001/f615e180 start 1 [2/0 us]
[ 3333.197647] option: option_instat_callback: error -2
[ 3333.198657] usb 5-6: usb suspend
[ 3335.001286] hub 5-0:1.0: hub_suspend
[ 3335.001362] usb usb5: bus auto-suspend
[ 3335.001386] ehci_hcd 0000:00:1d.7: suspend root hub
[ 3343.473220] usb usb5: usb auto-resume
[ 3343.473263] ehci_hcd 0000:00:1d.7: resume root hub
[ 3343.494209] hub 5-0:1.0: hub_resume
[ 3343.497470] hub 5-0:1.0: port 6: status 0507 change 0000
[ 3343.498583] hub 5-0:1.0: port 8: status 0501 change 0000
[ 3343.498897] hub 5-0:1.0: state 7 ports 8 chg 0100 evt fe00
[ 3343.501620] hub 5-0:1.0: port 8, status 0501, change 0000, 480 Mb/s
[ 3343.506794] usb 5-6: usb resume
[ 3343.533463] ehci_hcd 0000:00:1d.7: GetStatus port 6 status 001005
POWER sig=se0 PE CONNECT
[ 3343.548165] usb 5-6: finish resume
[ 3343.550850] ehci_hcd 0000:00:1d.7: reused qh f615e180 schedule
[ 3343.550893] usb 5-6: link qh2-0001/f615e180 start 1 [2/0 us]
[ 3343.550980]
[ 3343.550987] =======================================================
[ 3343.551017] [ INFO: possible circular locking dependency detected ]
[ 3343.551045] 2.6.31-rc3 #3
[ 3343.551064] -------------------------------------------------------
[ 3343.551090] sh/25228 is trying to acquire lock:
[ 3343.551113]  (&port->mutex){+.+...}, at: [<f8274322>]
option_resume+0xd9/0x16f [option]
[ 3343.551214]
[ 3343.551221] but task is already holding lock:
[ 3343.551245]  (&dev->pm_mutex/1){+.+.+.}, at: [<c11c313e>]
usb_external_resume_device+0x1e/0x60
[ 3343.551321]
[ 3343.551328] which lock already depends on the new lock.
[ 3343.551338]
[ 3343.551360]
[ 3343.551366] the existing dependency chain (in reverse order) is:
[ 3343.551392]
[ 3343.551399] -> #2 (&dev->pm_mutex/1){+.+.+.}:
[ 3343.551459]        [<c104fdac>] __lock_acquire+0x99d/0xb0c
[ 3343.551508]        [<c104ffc3>] lock_acquire+0xa8/0xc5
[ 3343.551550]        [<c126acb0>] __mutex_lock_common+0x3e/0x390
[ 3343.551575]        [<c126b08b>] mutex_lock_nested+0x29/0x31
[ 3343.551575]        [<c11c2a9c>] usb_autopm_do_interface+0x2d/0xbf
[ 3343.551575]        [<c11c2b47>] usb_autopm_get_interface+0xd/0xf
[ 3343.551575]        [<f82c3e4e>] serial_open+0x11b/0x1b9 [usbserial]
[ 3343.551575]        [<c1190662>] tty_open+0x290/0x38e
[ 3343.551575]        [<c10b0865>] chrdev_open+0x11a/0x131
[ 3343.551575]        [<c10ac956>] __dentry_open+0x156/0x24b
[ 3343.551575]        [<c10acae5>] nameidata_to_filp+0x2c/0x43
[ 3343.551575]        [<c10b716c>] do_filp_open+0x3ef/0x75a
[ 3343.551575]        [<c10ac709>] do_sys_open+0x4a/0xe2
[ 3343.551575]        [<c10ac7e3>] sys_open+0x1e/0x26
[ 3343.551575]        [<c1002f04>] sysenter_do_call+0x12/0x32
[ 3343.551575]        [<ffffffff>] 0xffffffff
[ 3343.551575]
[ 3343.551575] -> #1 (&serial->disc_mutex){+.+...}:
[ 3343.551575]        [<c104fdac>] __lock_acquire+0x99d/0xb0c
[ 3343.551575]        [<c104ffc3>] lock_acquire+0xa8/0xc5
[ 3343.551575]        [<c126acb0>] __mutex_lock_common+0x3e/0x390
[ 3343.551575]        [<c126b08b>] mutex_lock_nested+0x29/0x31
[ 3343.551575]        [<f82c3e40>] serial_open+0x10d/0x1b9 [usbserial]
[ 3343.551575]        [<c1190662>] tty_open+0x290/0x38e
[ 3343.551575]        [<c10b0865>] chrdev_open+0x11a/0x131
[ 3343.551575]        [<c10ac956>] __dentry_open+0x156/0x24b
[ 3343.551575]        [<c10acae5>] nameidata_to_filp+0x2c/0x43
[ 3343.551575]        [<c10b716c>] do_filp_open+0x3ef/0x75a
[ 3343.551575]        [<c10ac709>] do_sys_open+0x4a/0xe2
[ 3343.551575]        [<c10ac7e3>] sys_open+0x1e/0x26
[ 3343.551575]        [<c1002f04>] sysenter_do_call+0x12/0x32
[ 3343.551575]        [<ffffffff>] 0xffffffff
[ 3343.551575]
[ 3343.551575] -> #0 (&port->mutex){+.+...}:
[ 3343.551575]        [<c104fcbe>] __lock_acquire+0x8af/0xb0c
[ 3343.551575]        [<c104ffc3>] lock_acquire+0xa8/0xc5
[ 3343.551575]        [<c126acb0>] __mutex_lock_common+0x3e/0x390
[ 3343.551575]        [<c126b08b>] mutex_lock_nested+0x29/0x31
[ 3343.551575]        [<f8274322>] option_resume+0xd9/0x16f [option]
[ 3343.551575]        [<f82c282c>] usb_serial_resume+0x1e/0x29 [usbserial]
[ 3343.551575]        [<c11c23b2>] usb_resume_interface+0xbf/0x12a
[ 3343.551575]        [<c11c2813>] usb_resume_both+0xe6/0x108
[ 3343.551575]        [<c11c314e>] usb_external_resume_device+0x2e/0x60
[ 3343.551575]        [<c11c5aa9>] set_level+0xba/0x140
[ 3343.551575]        [<c11a78af>] dev_attr_store+0x1b/0x23
[ 3343.551575]        [<c10f099a>] sysfs_write_file+0xb9/0xe4
[ 3343.551575]        [<c10ae820>] vfs_write+0x84/0xdf
[ 3343.551575]        [<c10ae914>] sys_write+0x3b/0x60
[ 3343.551575]        [<c1002f04>] sysenter_do_call+0x12/0x32
[ 3343.551575]        [<ffffffff>] 0xffffffff
[ 3343.551575]
[ 3343.551575] other info that might help us debug this:
[ 3343.551575]
[ 3343.551575] 2 locks held by sh/25228:
[ 3343.551575]  #0:  (&buffer->mutex){+.+.+.}, at: [<c10f0906>]
sysfs_write_file+0x25/0xe4
[ 3343.551575]  #1:  (&dev->pm_mutex/1){+.+.+.}, at: [<c11c313e>]
usb_external_resume_device+0x1e/0x60
[ 3343.551575]
[ 3343.551575] stack backtrace:
[ 3343.551575] Pid: 25228, comm: sh Not tainted 2.6.31-rc3 #3
[ 3343.551575] Call Trace:
[ 3343.551575]  [<c1269a57>] ? printk+0xf/0x18
[ 3343.551575]  [<c104f14b>] print_circular_bug_tail+0x5d/0x68
[ 3343.551575]  [<c104fcbe>] __lock_acquire+0x8af/0xb0c
[ 3343.551575]  [<c104ffc3>] lock_acquire+0xa8/0xc5
[ 3343.551575]  [<f8274322>] ? option_resume+0xd9/0x16f [option]
[ 3343.551575]  [<c126acb0>] __mutex_lock_common+0x3e/0x390
[ 3343.551575]  [<f8274322>] ? option_resume+0xd9/0x16f [option]
[ 3343.551575]  [<c126b08b>] mutex_lock_nested+0x29/0x31
[ 3343.551575]  [<f8274322>] ? option_resume+0xd9/0x16f [option]
[ 3343.551575]  [<f8274322>] option_resume+0xd9/0x16f [option]
[ 3343.551575]  [<f82c282c>] usb_serial_resume+0x1e/0x29 [usbserial]
[ 3343.551575]  [<c11c23b2>] usb_resume_interface+0xbf/0x12a
[ 3343.551575]  [<c11c2813>] usb_resume_both+0xe6/0x108
[ 3343.551575]  [<c11c314e>] usb_external_resume_device+0x2e/0x60
[ 3343.551575]  [<c11c5aa9>] set_level+0xba/0x140
[ 3343.551575]  [<c11c59ef>] ? set_level+0x0/0x140
[ 3343.551575]  [<c11a78af>] dev_attr_store+0x1b/0x23
[ 3343.551575]  [<c10f099a>] sysfs_write_file+0xb9/0xe4
[ 3343.551575]  [<c10f08e1>] ? sysfs_write_file+0x0/0xe4
[ 3343.551575]  [<c10ae820>] vfs_write+0x84/0xdf
[ 3343.551575]  [<c10ae914>] sys_write+0x3b/0x60
[ 3343.551575]  [<c1002f04>] sysenter_do_call+0x12/0x32

--
+-----------------------------------+--------------------------+
| Dipl.-Phys. Thiemo Nagel          |                          |
| Technische Universitaet Muenchen  | Room    PH1 3276         |
| Physik-Department E18             |                          |
| James-Franck-Strasse              | Phone  +49 89 289-12379  |
| D-85747 Garching                  | Fax    +49 89 289-12570  |
+-----------------------------------+--------------------------+

Attachment: config-2.6.31-rc3.bz2
Description: application/bzip

Attachment: full-dmesg.bz2
Description: application/bzip