LinuxLists.cc - Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

2010-12-16 23:40:06

Subject: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

Hi,

The xhcd_hci driver causes some scary warnings to be printed on rmmod:

[ 33.189425] xhci_hcd 0000:04:00.0: remove, state 4
[ 33.189528] usb usb8: USB disconnect, address 1
[ 33.225678] xhci_hcd 0000:04:00.0: Host controller not halted, aborting reset.
[ 33.225678]
[ 33.225678] ======================================================
[ 33.225678] [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ]
[ 33.225678] 2.6.37-rc6+ #12
[ 33.225678] ------------------------------------------------------
[ 33.225678] rmmod/6075 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire:
[ 33.225678] (proc_subdir_lock){+.+...}, at: [<ffffffff81152aae>] remove_proc_entry+0x2e/0x2a0
[ 33.225678]
[ 33.225678] and this task is already holding:
[ 33.225678] (&(&xhci->lock)->rlock){-.....}, at: [<ffffffffa0134c9d>] xhci_stop+0x1d/0x80 [xhci_hcd]
[ 33.225678] which would create a new lock dependency:
[ 33.225678] (&(&xhci->lock)->rlock){-.....} -> (proc_subdir_lock){+.+...}
[ 33.225678]
[ 33.225678] but this new dependency connects a HARDIRQ-irq-safe lock:
[ 33.240111] (&(&xhci->lock)->rlock){-.....}
[ 33.240111] ... which became HARDIRQ-irq-safe at:
[ 33.240111] [<ffffffff8107a462>] __lock_acquire+0xc52/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffffa013e3f4>] xhci_irq+0x34/0x1c0 [xhci_hcd]
[ 33.240111] [<ffffffffa013e594>] xhci_msi_irq+0x14/0x20 [xhci_hcd]
[ 33.240111] [<ffffffff810a3e2a>] handle_IRQ_event+0x3a/0xe0
[ 33.240111] [<ffffffff810a66ee>] handle_edge_irq+0xce/0x180
[ 33.240111] [<ffffffff810057e4>] handle_irq+0x44/0xa0
[ 33.240111] [<ffffffff8100541d>] do_IRQ+0x6d/0xf0
[ 33.240111] [<ffffffff81495c53>] ret_from_intr+0x0/0xf
[ 33.240111]
[ 33.240111] to a HARDIRQ-irq-unsafe lock:
[ 33.240111] (proc_subdir_lock){+.+...}
[ 33.240111] ... which became HARDIRQ-irq-unsafe at:
[ 33.240111] ... [<ffffffff81079f75>] __lock_acquire+0x765/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81151f31>] __proc_create+0x61/0x150
[ 33.240111] [<ffffffff811528db>] proc_symlink+0x2b/0xb0
[ 33.240111] [<ffffffff81ac3254>] proc_root_init+0x69/0xc0
[ 33.240111] [<ffffffff81aa6c55>] start_kernel+0x3ca/0x3e9
[ 33.240111] [<ffffffff81aa6322>] x86_64_start_reservations+0x132/0x136
[ 33.240111] [<ffffffff81aa641c>] x86_64_start_kernel+0xf6/0xfd
[ 33.240111]
[ 33.240111] other info that might help us debug this:
[ 33.240111]
[ 33.240111] 3 locks held by rmmod/6075:
[ 33.240111] #0: (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff8132e56c>] driver_detach+0x4c/0xd0
[ 33.240111] #1: (&__lockdep_no_validate__){+.+.+.}, at: [<ffffffff8132e57a>] driver_detach+0x5a/0xd0
[ 33.240111] #2: (&(&xhci->lock)->rlock){-.....}, at: [<ffffffffa0134c9d>] xhci_stop+0x1d/0x80 [xhci_hcd]
[ 33.240111]
[ 33.240111] the dependencies between HARDIRQ-irq-safe lock and the holding lock:
[ 33.240111] -> (&(&xhci->lock)->rlock){-.....} ops: 14 {
[ 33.240111] IN-HARDIRQ-W at:
[ 33.240111] [<ffffffff8107a462>] __lock_acquire+0xc52/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffffa013e3f4>] xhci_irq+0x34/0x1c0 [xhci_hcd]
[ 33.240111] [<ffffffffa013e594>] xhci_msi_irq+0x14/0x20 [xhci_hcd]
[ 33.240111] [<ffffffff810a3e2a>] handle_IRQ_event+0x3a/0xe0
[ 33.240111] [<ffffffff810a66ee>] handle_edge_irq+0xce/0x180
[ 33.240111] [<ffffffff810057e4>] handle_irq+0x44/0xa0
[ 33.240111] [<ffffffff8100541d>] do_IRQ+0x6d/0xf0
[ 33.240111] [<ffffffff81495c53>] ret_from_intr+0x0/0xf
[ 33.240111] INITIAL USE at:
[ 33.240111] [<ffffffff81079bd9>] __lock_acquire+0x3c9/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffffa013e3f4>] xhci_irq+0x34/0x1c0 [xhci_hcd]
[ 33.240111] [<ffffffffa013e594>] xhci_msi_irq+0x14/0x20 [xhci_hcd]
[ 33.240111] [<ffffffff810a3e2a>] handle_IRQ_event+0x3a/0xe0
[ 33.240111] [<ffffffff810a66ee>] handle_edge_irq+0xce/0x180
[ 33.240111] [<ffffffff810057e4>] handle_irq+0x44/0xa0
[ 33.240111] [<ffffffff8100541d>] do_IRQ+0x6d/0xf0
[ 33.240111] [<ffffffff81495c53>] ret_from_intr+0x0/0xf
[ 33.240111] }
[ 33.240111] ... key at: [<ffffffffa0149314>] __key.26332+0x0/0xffffffffffff649c [xhci_hcd]
[ 33.240111] ... acquired at:
[ 33.240111] [<ffffffff81079100>] check_irq_usage+0x60/0xf0
[ 33.240111] [<ffffffff8107a840>] __lock_acquire+0x1030/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81152aae>] remove_proc_entry+0x2e/0x2a0
[ 33.240111] [<ffffffff810a779c>] unregister_handler_proc+0x2c/0x40
[ 33.240111] [<ffffffff810a4500>] __free_irq+0x100/0x250
[ 33.240111] [<ffffffff810a4692>] free_irq+0x42/0x80
[ 33.240111] [<ffffffffa01345be>] xhci_free_irq+0x7e/0x90 [xhci_hcd]
[ 33.240111] [<ffffffffa01345f0>] xhci_cleanup_msix+0x20/0x80 [xhci_hcd]
[ 33.240111] [<ffffffffa0134cb5>] xhci_stop+0x35/0x80 [xhci_hcd]
[ 33.240111] [<ffffffff813799f6>] usb_remove_hcd+0xe6/0x160
[ 33.240111] [<ffffffff81389f01>] usb_hcd_pci_remove+0x51/0xc0
[ 33.240111] [<ffffffff811e415d>] pci_device_remove+0x4d/0x110
[ 33.240111] [<ffffffff8132dd70>] __device_release_driver+0x70/0xe0
[ 33.240111] [<ffffffff8132e5e8>] driver_detach+0xc8/0xd0
[ 33.240111] [<ffffffff8132dbe6>] bus_remove_driver+0x96/0x100
[ 33.240111] [<ffffffff8132e679>] driver_unregister+0x59/0x90
[ 33.240111] [<ffffffff811e3dbf>] pci_unregister_driver+0x3f/0xa0
[ 33.240111] [<ffffffffa013a7d0>] xhci_unregister_pci+0x10/0x20 [xhci_hcd]
[ 33.240111] [<ffffffffa013f7ae>] xhci_hcd_cleanup+0x9/0xb [xhci_hcd]
[ 33.240111] [<ffffffff81085a07>] sys_delete_module+0x167/0x250
[ 33.240111] [<ffffffff8100273b>] system_call_fastpath+0x16/0x1b
[ 33.240111]
[ 33.240111]
[ 33.240111] the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock:
[ 33.240111] -> (proc_subdir_lock){+.+...} ops: 6970 {
[ 33.240111] HARDIRQ-ON-W at:
[ 33.240111] [<ffffffff81079f75>] __lock_acquire+0x765/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81151f31>] __proc_create+0x61/0x150
[ 33.240111] [<ffffffff811528db>] proc_symlink+0x2b/0xb0
[ 33.240111] [<ffffffff81ac3254>] proc_root_init+0x69/0xc0
[ 33.240111] [<ffffffff81aa6c55>] start_kernel+0x3ca/0x3e9
[ 33.240111] [<ffffffff81aa6322>] x86_64_start_reservations+0x132/0x136
[ 33.240111] [<ffffffff81aa641c>] x86_64_start_kernel+0xf6/0xfd
[ 33.240111] SOFTIRQ-ON-W at:
[ 33.240111] [<ffffffff81079fb0>] __lock_acquire+0x7a0/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81151f31>] __proc_create+0x61/0x150
[ 33.240111] [<ffffffff811528db>] proc_symlink+0x2b/0xb0
[ 33.240111] [<ffffffff81ac3254>] proc_root_init+0x69/0xc0
[ 33.240111] [<ffffffff81aa6c55>] start_kernel+0x3ca/0x3e9
[ 33.240111] [<ffffffff81aa6322>] x86_64_start_reservations+0x132/0x136
[ 33.240111] [<ffffffff81aa641c>] x86_64_start_kernel+0xf6/0xfd
[ 33.240111] INITIAL USE at:
[ 33.240111] [<ffffffff81079bd9>] __lock_acquire+0x3c9/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81151f31>] __proc_create+0x61/0x150
[ 33.240111] [<ffffffff811528db>] proc_symlink+0x2b/0xb0
[ 33.240111] [<ffffffff81ac3254>] proc_root_init+0x69/0xc0
[ 33.240111] [<ffffffff81aa6c55>] start_kernel+0x3ca/0x3e9
[ 33.240111] [<ffffffff81aa6322>] x86_64_start_reservations+0x132/0x136
[ 33.240111] [<ffffffff81aa641c>] x86_64_start_kernel+0xf6/0xfd
[ 33.240111] }
[ 33.240111] ... key at: [<ffffffff81a443f8>] proc_subdir_lock+0x18/0x40
[ 33.240111] ... acquired at:
[ 33.240111] [<ffffffff81079100>] check_irq_usage+0x60/0xf0
[ 33.240111] [<ffffffff8107a840>] __lock_acquire+0x1030/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81152aae>] remove_proc_entry+0x2e/0x2a0
[ 33.240111] [<ffffffff810a779c>] unregister_handler_proc+0x2c/0x40
[ 33.240111] [<ffffffff810a4500>] __free_irq+0x100/0x250
[ 33.240111] [<ffffffff810a4692>] free_irq+0x42/0x80
[ 33.240111] [<ffffffffa01345be>] xhci_free_irq+0x7e/0x90 [xhci_hcd]
[ 33.240111] [<ffffffffa01345f0>] xhci_cleanup_msix+0x20/0x80 [xhci_hcd]
[ 33.240111] [<ffffffffa0134cb5>] xhci_stop+0x35/0x80 [xhci_hcd]
[ 33.240111] [<ffffffff813799f6>] usb_remove_hcd+0xe6/0x160
[ 33.240111] [<ffffffff81389f01>] usb_hcd_pci_remove+0x51/0xc0
[ 33.240111] [<ffffffff811e415d>] pci_device_remove+0x4d/0x110
[ 33.240111] [<ffffffff8132dd70>] __device_release_driver+0x70/0xe0
[ 33.240111] [<ffffffff8132e5e8>] driver_detach+0xc8/0xd0
[ 33.240111] [<ffffffff8132dbe6>] bus_remove_driver+0x96/0x100
[ 33.240111] [<ffffffff8132e679>] driver_unregister+0x59/0x90
[ 33.240111] [<ffffffff811e3dbf>] pci_unregister_driver+0x3f/0xa0
[ 33.240111] [<ffffffffa013a7d0>] xhci_unregister_pci+0x10/0x20 [xhci_hcd]
[ 33.240111] [<ffffffffa013f7ae>] xhci_hcd_cleanup+0x9/0xb [xhci_hcd]
[ 33.240111] [<ffffffff81085a07>] sys_delete_module+0x167/0x250
[ 33.240111] [<ffffffff8100273b>] system_call_fastpath+0x16/0x1b
[ 33.240111]
[ 33.240111]
[ 33.240111] stack backtrace:
[ 33.240111] Pid: 6075, comm: rmmod Not tainted 2.6.37-rc6+ #12
[ 33.240111] Call Trace:
[ 33.240111] [<ffffffff81079097>] check_usage+0x497/0x4a0
[ 33.240111] [<ffffffff81079100>] check_irq_usage+0x60/0xf0
[ 33.240111] [<ffffffff8107a840>] __lock_acquire+0x1030/0x1ca0
[ 33.240111] [<ffffffff8107b9f7>] lock_acquire+0x57/0x70
[ 33.240111] [<ffffffff81152aae>] ? remove_proc_entry+0x2e/0x2a0
[ 33.240111] [<ffffffff81494e06>] _raw_spin_lock+0x36/0x50
[ 33.240111] [<ffffffff81152aae>] ? remove_proc_entry+0x2e/0x2a0
[ 33.240111] [<ffffffff81152aae>] remove_proc_entry+0x2e/0x2a0
[ 33.240111] [<ffffffff8104a939>] ? vprintk+0x2f9/0x4b0
[ 33.240111] [<ffffffff810a779c>] unregister_handler_proc+0x2c/0x40
[ 33.240111] [<ffffffff810a4500>] __free_irq+0x100/0x250
[ 33.240111] [<ffffffff810a4692>] free_irq+0x42/0x80
[ 33.240111] [<ffffffffa01345be>] xhci_free_irq+0x7e/0x90 [xhci_hcd]
[ 33.240111] [<ffffffffa01345f0>] xhci_cleanup_msix+0x20/0x80 [xhci_hcd]
[ 33.240111] [<ffffffffa0134cb5>] xhci_stop+0x35/0x80 [xhci_hcd]
[ 33.240111] [<ffffffff813799f6>] usb_remove_hcd+0xe6/0x160
[ 33.240111] [<ffffffff81389f01>] usb_hcd_pci_remove+0x51/0xc0
[ 33.240111] [<ffffffff811e415d>] pci_device_remove+0x4d/0x110
[ 33.240111] [<ffffffff8132dd70>] __device_release_driver+0x70/0xe0
[ 33.240111] [<ffffffff8132e5e8>] driver_detach+0xc8/0xd0
[ 33.240111] [<ffffffff8132dbe6>] bus_remove_driver+0x96/0x100
[ 33.240111] [<ffffffff8132e679>] driver_unregister+0x59/0x90
[ 33.240111] [<ffffffff811e3dbf>] pci_unregister_driver+0x3f/0xa0
[ 33.240111] [<ffffffffa013a7d0>] xhci_unregister_pci+0x10/0x20 [xhci_hcd]
[ 33.240111] [<ffffffffa013f7ae>] xhci_hcd_cleanup+0x9/0xb [xhci_hcd]
[ 33.240111] [<ffffffff81085a07>] sys_delete_module+0x167/0x250
[ 33.240111] [<ffffffff8100276c>] ? sysret_check+0x27/0x62
[ 33.240111] [<ffffffff8107c3bd>] ? trace_hardirqs_on_caller+0x12d/0x170
[ 33.240111] [<ffffffff8100273b>] system_call_fastpath+0x16/0x1b
[ 33.240111] BUG: sleeping function called from invalid context at /home/rafael/src/linux-2.6/kernel/mutex.c:278
[ 33.240111] in_atomic(): 1, irqs_disabled(): 1, pid: 6075, name: rmmod
[ 33.240111] INFO: lockdep is turned off.
[ 33.240111] irq event stamp: 4560
[ 33.240111] hardirqs last enabled at (4559): [<ffffffff8149571d>] _raw_spin_unlock_irqrestore+0x5d/0x70
[ 33.240111] hardirqs last disabled at (4560): [<ffffffff81494e92>] _raw_spin_lock_irq+0x12/0x50
[ 33.240111] softirqs last enabled at (4494): [<ffffffff81400845>] sk_filter+0xd5/0x100
[ 33.240111] softirqs last disabled at (4492): [<ffffffff814007ad>] sk_filter+0x3d/0x100
[ 33.240111] Pid: 6075, comm: rmmod Not tainted 2.6.37-rc6+ #12
[ 33.240111] Call Trace:
[ 33.240111] [<ffffffff81079290>] ? print_irqtrace_events+0xd0/0xe0
[ 33.240111] [<ffffffff81036783>] __might_sleep+0x103/0x130
[ 33.240111] [<ffffffff81492f73>] mutex_lock_nested+0x33/0x380
[ 33.240111] [<ffffffff814956fd>] ? _raw_spin_unlock_irqrestore+0x3d/0x70
[ 33.240111] [<ffffffff810a39de>] ? dynamic_irq_cleanup+0xde/0x100
[ 33.240111] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
[ 33.240111] [<ffffffff81022008>] destroy_irq+0x78/0x90
[ 33.240111] [<ffffffff810222c9>] native_teardown_msi_irq+0x9/0x10
[ 33.240111] [<ffffffff811ee0b0>] default_teardown_msi_irqs+0x70/0xa0
[ 33.240111] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
[ 33.240111] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
[ 33.240111] [<ffffffffa0134609>] xhci_cleanup_msix+0x39/0x80 [xhci_hcd]
[ 33.240111] [<ffffffffa0134cb5>] xhci_stop+0x35/0x80 [xhci_hcd]
[ 33.240111] [<ffffffff813799f6>] usb_remove_hcd+0xe6/0x160
[ 33.240111] [<ffffffff81389f01>] usb_hcd_pci_remove+0x51/0xc0
[ 33.240111] [<ffffffff811e415d>] pci_device_remove+0x4d/0x110
[ 33.240111] [<ffffffff8132dd70>] __device_release_driver+0x70/0xe0
[ 33.240111] [<ffffffff8132e5e8>] driver_detach+0xc8/0xd0
[ 33.240111] [<ffffffff8132dbe6>] bus_remove_driver+0x96/0x100
[ 33.240111] [<ffffffff8132e679>] driver_unregister+0x59/0x90
[ 33.240111] [<ffffffff811e3dbf>] pci_unregister_driver+0x3f/0xa0
[ 33.240111] [<ffffffffa013a7d0>] xhci_unregister_pci+0x10/0x20 [xhci_hcd]
[ 33.240111] [<ffffffffa013f7ae>] xhci_hcd_cleanup+0x9/0xb [xhci_hcd]
[ 33.240111] [<ffffffff81085a07>] sys_delete_module+0x167/0x250
[ 33.240111] [<ffffffff8100276c>] ? sysret_check+0x27/0x62
[ 33.240111] [<ffffffff8107c3bd>] ? trace_hardirqs_on_caller+0x12d/0x170
[ 33.240111] [<ffffffff8100273b>] system_call_fastpath+0x16/0x1b
[ 33.240111] ------------[ cut here ]------------
[ 33.240111] WARNING: at /home/rafael/src/linux-2.6/kernel/smp.c:432 smp_call_function_many+0xac/0x1f0()
[ 33.240111] Hardware name: MS-7640
[ 33.240111] Modules linked in: nfsd lockd nfs_acl auth_rpcgss sunrpc exportfs snd_pcm_oss snd_mixer_oss snd_seq snd_seq_device edd ipv6 cpufreq_conservative cpufreq_ondemand cpufreq_userspace cpufreq_powersave powernow_k8 freq_table mperf ext3 jbd dm_mod snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_timer snd sr_mod soundcore firewire_ohci evdev cdrom firewire_core serio_raw joydev snd_page_alloc button sg r8169 mii xhci_hcd(-) crc_itu_t ext4 jbd2 crc16 raid456 async_pq async_xor xor async_memcpy async_raid6_recov raid6_pq async_tx raid10 raid0 ohci_hcd ehci_hcd sd_mod crc_t10dif rtc_cmos rtc_core rtc_lib fan processor pata_jmicron thermal
[ 33.240111] Pid: 6075, comm: rmmod Not tainted 2.6.37-rc6+ #12
[ 33.240111] Call Trace:
[ 33.240111] [<ffffffff81049e5a>] warn_slowpath_common+0x7a/0xb0
[ 33.240111] [<ffffffff81030f60>] ? do_flush_tlb_all+0x0/0x50
[ 33.240111] [<ffffffff81049ea5>] warn_slowpath_null+0x15/0x20
[ 33.240111] [<ffffffff81082c5c>] smp_call_function_many+0xac/0x1f0
[ 33.240111] [<ffffffff81030f60>] ? do_flush_tlb_all+0x0/0x50
[ 33.240111] [<ffffffff81082de1>] smp_call_function+0x41/0x80
[ 33.240111] [<ffffffff81030f60>] ? do_flush_tlb_all+0x0/0x50
[ 33.240111] [<ffffffff8104fba5>] on_each_cpu+0x35/0x80
[ 33.240111] [<ffffffff810312c7>] flush_tlb_all+0x17/0x20
[ 33.240111] [<ffffffff810e0990>] remove_vm_area+0x90/0xc0
[ 33.240111] [<ffffffff8102c1a1>] iounmap+0x91/0xe0
[ 33.240111] [<ffffffff811edba9>] free_msi_irqs+0x109/0x110
[ 33.240111] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
[ 33.240111] [<ffffffffa0134609>] xhci_cleanup_msix+0x39/0x80 [xhci_hcd]
[ 33.240111] [<ffffffffa0134cb5>] xhci_stop+0x35/0x80 [xhci_hcd]
[ 33.240111] [<ffffffff813799f6>] usb_remove_hcd+0xe6/0x160
[ 33.240111] [<ffffffff81389f01>] usb_hcd_pci_remove+0x51/0xc0
[ 33.240111] [<ffffffff811e415d>] pci_device_remove+0x4d/0x110
[ 33.240111] [<ffffffff8132dd70>] __device_release_driver+0x70/0xe0
[ 33.240111] [<ffffffff8132e5e8>] driver_detach+0xc8/0xd0
[ 33.240111] [<ffffffff8132dbe6>] bus_remove_driver+0x96/0x100
[ 33.240111] [<ffffffff8132e679>] driver_unregister+0x59/0x90
[ 33.240111] [<ffffffff811e3dbf>] pci_unregister_driver+0x3f/0xa0
[ 33.240111] [<ffffffffa013a7d0>] xhci_unregister_pci+0x10/0x20 [xhci_hcd]
[ 33.240111] [<ffffffffa013f7ae>] xhci_hcd_cleanup+0x9/0xb [xhci_hcd]
[ 33.240111] [<ffffffff81085a07>] sys_delete_module+0x167/0x250
[ 33.240111] [<ffffffff8100276c>] ? sysret_check+0x27/0x62
[ 33.240111] [<ffffffff8107c3bd>] ? trace_hardirqs_on_caller+0x12d/0x170
[ 33.240111] [<ffffffff8100273b>] system_call_fastpath+0x16/0x1b
[ 33.240111] ---[ end trace 78a8387880057ad9 ]---
[ 33.269230] xhci_hcd 0000:04:00.0: USB bus 8 deregistered
[ 33.486574] xhci_hcd 0000:04:00.0: PCI INT A disabled
[ 69.159848] xhci_hcd 0000:04:00.0: PCI INT A -> GSI 48 (level, low) -> IRQ 48
[ 69.161130] xhci_hcd 0000:04:00.0: enabling bus mastering
[ 69.162281] xhci_hcd 0000:04:00.0: setting latency timer to 64
[ 69.163433] xhci_hcd 0000:04:00.0: xHCI Host Controller
[ 69.164848] xhci_hcd 0000:04:00.0: new USB bus registered, assigned bus number 8
[ 69.193629] xhci_hcd 0000:04:00.0: enabling Mem-Wr-Inval
[ 69.194848] xhci_hcd 0000:04:00.0: irq 48, io mem 0xfe5fe000
[ 69.196022] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
[ 69.197175] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
[ 69.198292] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
[ 69.199403] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
[ 69.200527] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
[ 69.201620] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
[ 69.202703] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X
[ 69.203883] usb usb8: No SuperSpeed endpoint companion for config 1 interface 0 altsetting 0 ep 129: using minimum values
[ 69.205038] usb usb8: New USB device found, idVendor=1d6b, idProduct=0003
[ 69.206166] usb usb8: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 69.207320] usb usb8: Product: xHCI Host Controller
[ 69.208453] usb usb8: Manufacturer: Linux 2.6.37-rc6+ xhci_hcd
[ 69.208458] usb usb8: SerialNumber: 0000:04:00.0
[ 69.208789] xHCI xhci_add_endpoint called for root hub
[ 69.208791] xHCI xhci_check_bandwidth called for root hub
[ 69.208919] hub 8-0:1.0: USB hub found
[ 69.208929] hub 8-0:1.0: 4 ports detected

and during shutdown (I believe the warnings are the same or analogous to the
above).

I tested with the attached patch from Andiry applied and I got the following
BUG during resume:

[ 91.703778] sd 0:0:0:0: [sda] Starting disk
[ 91.704054] sd 2:0:0:0: [sdb] Starting disk
[ 91.703680] xhci_hcd 0000:04:00.0: Host controller not halted, aborting reset.
[ 91.703680] BUG: sleeping function called from invalid context at /home/rafael/src/linux-2.6/kernel/mutex.c:278
[ 91.703680] in_atomic(): 1, irqs_disabled(): 1, pid: 1234, name: kworker/u:6
[ 91.703680] INFO: lockdep is turned off.
[ 91.703680] irq event stamp: 24060
[ 91.703680] hardirqs last enabled at (24059): [<ffffffff810aa071>] rcu_note_context_switch+0xa1/0x1c0
[ 91.703680] hardirqs last disabled at (24060): [<ffffffff81494e92>] _raw_spin_lock_irq+0x12/0x50
[ 91.703680] softirqs last enabled at (20026): [<ffffffff8105056e>] __do_softirq+0x11e/0x160
[ 91.703680] softirqs last disabled at (20011): [<ffffffff8100368c>] call_softirq+0x1c/0x30
[ 91.703680] Pid: 1234, comm: kworker/u:6 Tainted: G W 2.6.37-rc6+ #12
[ 91.703680] Call Trace:
[ 91.703680] [<ffffffff81079290>] ? print_irqtrace_events+0xd0/0xe0
[ 91.703680] [<ffffffff81036783>] __might_sleep+0x103/0x130
[ 91.703680] [<ffffffff81492f73>] mutex_lock_nested+0x33/0x380
[ 91.703680] [<ffffffff81495727>] ? _raw_spin_unlock_irqrestore+0x67/0x70
[ 91.703680] [<ffffffff810a39de>] ? dynamic_irq_cleanup+0xde/0x100
[ 91.703680] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
[ 91.703680] [<ffffffff81022008>] destroy_irq+0x78/0x90
[ 91.703680] [<ffffffff810222c9>] native_teardown_msi_irq+0x9/0x10
[ 91.703680] [<ffffffff811ee0b0>] default_teardown_msi_irqs+0x70/0xa0
[ 91.703680] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
[ 91.703680] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
[ 91.703680] [<ffffffffa03f0609>] xhci_cleanup_msix+0x39/0x80 [xhci_hcd]
[ 91.703680] [<ffffffffa03f111c>] xhci_resume+0x1ac/0x250 [xhci_hcd]
[ 91.703680] [<ffffffffa03f65c4>] xhci_pci_resume+0x14/0x20 [xhci_hcd]
[ 91.703680] [<ffffffff8138996b>] resume_common+0xbb/0x140
[ 91.703680] [<ffffffff81389a5e>] hcd_pci_restore+0xe/0x10
[ 91.703680] [<ffffffff811e36f3>] pci_pm_restore+0x63/0xb0
[ 91.703680] [<ffffffff813334bd>] pm_op+0x19d/0x1c0
[ 91.703680] [<ffffffff81333be4>] device_resume+0x94/0x220
[ 91.703680] [<ffffffff81333d8c>] async_resume+0x1c/0x50
[ 91.703680] [<ffffffff8106e6e6>] async_run_entry_fn+0x86/0x160
[ 91.703680] [<ffffffff81060672>] process_one_work+0x1a2/0x450
[ 91.703680] [<ffffffff81060614>] ? process_one_work+0x144/0x450
[ 91.703680] [<ffffffff811d2704>] ? do_raw_spin_lock+0x104/0x170
[ 91.703680] [<ffffffff8106e660>] ? async_run_entry_fn+0x0/0x160
[ 91.703680] [<ffffffff81061e32>] worker_thread+0x162/0x340
[ 91.703680] [<ffffffff81061cd0>] ? worker_thread+0x0/0x340
[ 91.703680] [<ffffffff81066836>] kthread+0x96/0xa0
[ 91.703680] [<ffffffff81003594>] kernel_thread_helper+0x4/0x10
[ 91.703680] [<ffffffff81036fdb>] ? finish_task_switch+0x7b/0xe0
[ 91.703680] [<ffffffff81495d00>] ? restore_args+0x0/0x30
[ 91.703680] [<ffffffff810667a0>] ? kthread+0x0/0xa0
[ 91.703680] [<ffffffff81003590>] ? kernel_thread_helper+0x0/0x10
[ 91.706248] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
[ 91.706251] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
[ 91.706253] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
[ 91.706256] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
[ 91.706258] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
[ 91.706260] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
[ 91.706262] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X

The issues appear to be 100% reproducible.

Thanks,
Rafael

Attachments:

xHCI-synchronize-interrupts-in-xhci_suspend.patch (2.71 kB)

2010-12-17 08:26:31

by Andiry Xu

[permalink] [raw]

Subject: RE: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

>
> and during shutdown (I believe the warnings are the same or analogous
to
> the
> above).
>
> I tested with the attached patch from Andiry applied and I got the
> following
> BUG during resume:

Does this bug occurs without the synchronize irq patch? Seems the rmmod,
shutdown and resume bugs are caused by xhci_cleanup_msix().

>
> [ 91.703778] sd 0:0:0:0: [sda] Starting disk
> [ 91.704054] sd 2:0:0:0: [sdb] Starting disk
> [ 91.703680] xhci_hcd 0000:04:00.0: Host controller not halted,
aborting
> reset.
> [ 91.703680] BUG: sleeping function called from invalid context at
> /home/rafael/src/linux-2.6/kernel/mutex.c:278
> [ 91.703680] in_atomic(): 1, irqs_disabled(): 1, pid: 1234, name:
> kworker/u:6
> [ 91.703680] INFO: lockdep is turned off.
> [ 91.703680] irq event stamp: 24060
> [ 91.703680] hardirqs last enabled at (24059): [<ffffffff810aa071>]
> rcu_note_context_switch+0xa1/0x1c0
> [ 91.703680] hardirqs last disabled at (24060): [<ffffffff81494e92>]
> _raw_spin_lock_irq+0x12/0x50
> [ 91.703680] softirqs last enabled at (20026): [<ffffffff8105056e>]
> __do_softirq+0x11e/0x160
> [ 91.703680] softirqs last disabled at (20011): [<ffffffff8100368c>]
> call_softirq+0x1c/0x30
> [ 91.703680] Pid: 1234, comm: kworker/u:6 Tainted: G W
2.6.37-
> rc6+ #12
> [ 91.703680] Call Trace:
> [ 91.703680] [<ffffffff81079290>] ? print_irqtrace_events+0xd0/0xe0
> [ 91.703680] [<ffffffff81036783>] __might_sleep+0x103/0x130
> [ 91.703680] [<ffffffff81492f73>] mutex_lock_nested+0x33/0x380
> [ 91.703680] [<ffffffff81495727>] ?
> _raw_spin_unlock_irqrestore+0x67/0x70
> [ 91.703680] [<ffffffff810a39de>] ? dynamic_irq_cleanup+0xde/0x100
> [ 91.703680] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
> [ 91.703680] [<ffffffff81022008>] destroy_irq+0x78/0x90
> [ 91.703680] [<ffffffff810222c9>] native_teardown_msi_irq+0x9/0x10
> [ 91.703680] [<ffffffff811ee0b0>]
default_teardown_msi_irqs+0x70/0xa0
> [ 91.703680] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
> [ 91.703680] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
> [ 91.703680] [<ffffffffa03f0609>] xhci_cleanup_msix+0x39/0x80
[xhci_hcd]
> [ 91.703680] [<ffffffffa03f111c>] xhci_resume+0x1ac/0x250
[xhci_hcd]
> [ 91.703680] [<ffffffffa03f65c4>] xhci_pci_resume+0x14/0x20
[xhci_hcd]
> [ 91.703680] [<ffffffff8138996b>] resume_common+0xbb/0x140
> [ 91.703680] [<ffffffff81389a5e>] hcd_pci_restore+0xe/0x10
> [ 91.703680] [<ffffffff811e36f3>] pci_pm_restore+0x63/0xb0
> [ 91.703680] [<ffffffff813334bd>] pm_op+0x19d/0x1c0
> [ 91.703680] [<ffffffff81333be4>] device_resume+0x94/0x220
> [ 91.703680] [<ffffffff81333d8c>] async_resume+0x1c/0x50
> [ 91.703680] [<ffffffff8106e6e6>] async_run_entry_fn+0x86/0x160
> [ 91.703680] [<ffffffff81060672>] process_one_work+0x1a2/0x450
> [ 91.703680] [<ffffffff81060614>] ? process_one_work+0x144/0x450
> [ 91.703680] [<ffffffff811d2704>] ? do_raw_spin_lock+0x104/0x170
> [ 91.703680] [<ffffffff8106e660>] ? async_run_entry_fn+0x0/0x160
> [ 91.703680] [<ffffffff81061e32>] worker_thread+0x162/0x340
> [ 91.703680] [<ffffffff81061cd0>] ? worker_thread+0x0/0x340
> [ 91.703680] [<ffffffff81066836>] kthread+0x96/0xa0
> [ 91.703680] [<ffffffff81003594>] kernel_thread_helper+0x4/0x10
> [ 91.703680] [<ffffffff81036fdb>] ? finish_task_switch+0x7b/0xe0
> [ 91.703680] [<ffffffff81495d00>] ? restore_args+0x0/0x30
> [ 91.703680] [<ffffffff810667a0>] ? kthread+0x0/0xa0
> [ 91.703680] [<ffffffff81003590>] ? kernel_thread_helper+0x0/0x10
> [ 91.706248] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
> [ 91.706251] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
> [ 91.706253] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
> [ 91.706256] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
> [ 91.706258] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
> [ 91.706260] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
> [ 91.706262] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X
>
> The issues appear to be 100% reproducible.
>

I'm not able to reproduce the issue. Can you specify your kernel version
and attach your .config?

Thanks,
Andiry

2010-12-17 13:22:39

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

On Friday, December 17, 2010, Xu, Andiry wrote:
> >
> > and during shutdown (I believe the warnings are the same or analogous
> to
> > the
> > above).
> >
> > I tested with the attached patch from Andiry applied and I got the
> > following
> > BUG during resume:
>
> Does this bug occurs without the synchronize irq patch?

Yes, it does.

> Seems the rmmod, shutdown and resume bugs are caused by xhci_cleanup_msix().
>
> >
> > [ 91.703778] sd 0:0:0:0: [sda] Starting disk
> > [ 91.704054] sd 2:0:0:0: [sdb] Starting disk
> > [ 91.703680] xhci_hcd 0000:04:00.0: Host controller not halted,
> aborting
> > reset.
> > [ 91.703680] BUG: sleeping function called from invalid context at
> > /home/rafael/src/linux-2.6/kernel/mutex.c:278
> > [ 91.703680] in_atomic(): 1, irqs_disabled(): 1, pid: 1234, name:
> > kworker/u:6
> > [ 91.703680] INFO: lockdep is turned off.
> > [ 91.703680] irq event stamp: 24060
> > [ 91.703680] hardirqs last enabled at (24059): [<ffffffff810aa071>]
> > rcu_note_context_switch+0xa1/0x1c0
> > [ 91.703680] hardirqs last disabled at (24060): [<ffffffff81494e92>]
> > _raw_spin_lock_irq+0x12/0x50
> > [ 91.703680] softirqs last enabled at (20026): [<ffffffff8105056e>]
> > __do_softirq+0x11e/0x160
> > [ 91.703680] softirqs last disabled at (20011): [<ffffffff8100368c>]
> > call_softirq+0x1c/0x30
> > [ 91.703680] Pid: 1234, comm: kworker/u:6 Tainted: G W
> 2.6.37-
> > rc6+ #12
> > [ 91.703680] Call Trace:
> > [ 91.703680] [<ffffffff81079290>] ? print_irqtrace_events+0xd0/0xe0
> > [ 91.703680] [<ffffffff81036783>] __might_sleep+0x103/0x130
> > [ 91.703680] [<ffffffff81492f73>] mutex_lock_nested+0x33/0x380
> > [ 91.703680] [<ffffffff81495727>] ?
> > _raw_spin_unlock_irqrestore+0x67/0x70
> > [ 91.703680] [<ffffffff810a39de>] ? dynamic_irq_cleanup+0xde/0x100
> > [ 91.703680] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
> > [ 91.703680] [<ffffffff81022008>] destroy_irq+0x78/0x90
> > [ 91.703680] [<ffffffff810222c9>] native_teardown_msi_irq+0x9/0x10
> > [ 91.703680] [<ffffffff811ee0b0>]
> default_teardown_msi_irqs+0x70/0xa0
> > [ 91.703680] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
> > [ 91.703680] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
> > [ 91.703680] [<ffffffffa03f0609>] xhci_cleanup_msix+0x39/0x80
> [xhci_hcd]
> > [ 91.703680] [<ffffffffa03f111c>] xhci_resume+0x1ac/0x250
> [xhci_hcd]
> > [ 91.703680] [<ffffffffa03f65c4>] xhci_pci_resume+0x14/0x20
> [xhci_hcd]
> > [ 91.703680] [<ffffffff8138996b>] resume_common+0xbb/0x140
> > [ 91.703680] [<ffffffff81389a5e>] hcd_pci_restore+0xe/0x10
> > [ 91.703680] [<ffffffff811e36f3>] pci_pm_restore+0x63/0xb0
> > [ 91.703680] [<ffffffff813334bd>] pm_op+0x19d/0x1c0
> > [ 91.703680] [<ffffffff81333be4>] device_resume+0x94/0x220
> > [ 91.703680] [<ffffffff81333d8c>] async_resume+0x1c/0x50
> > [ 91.703680] [<ffffffff8106e6e6>] async_run_entry_fn+0x86/0x160
> > [ 91.703680] [<ffffffff81060672>] process_one_work+0x1a2/0x450
> > [ 91.703680] [<ffffffff81060614>] ? process_one_work+0x144/0x450
> > [ 91.703680] [<ffffffff811d2704>] ? do_raw_spin_lock+0x104/0x170
> > [ 91.703680] [<ffffffff8106e660>] ? async_run_entry_fn+0x0/0x160
> > [ 91.703680] [<ffffffff81061e32>] worker_thread+0x162/0x340
> > [ 91.703680] [<ffffffff81061cd0>] ? worker_thread+0x0/0x340
> > [ 91.703680] [<ffffffff81066836>] kthread+0x96/0xa0
> > [ 91.703680] [<ffffffff81003594>] kernel_thread_helper+0x4/0x10
> > [ 91.703680] [<ffffffff81036fdb>] ? finish_task_switch+0x7b/0xe0
> > [ 91.703680] [<ffffffff81495d00>] ? restore_args+0x0/0x30
> > [ 91.703680] [<ffffffff810667a0>] ? kthread+0x0/0xa0
> > [ 91.703680] [<ffffffff81003590>] ? kernel_thread_helper+0x0/0x10
> > [ 91.706248] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
> > [ 91.706251] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
> > [ 91.706253] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
> > [ 91.706256] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
> > [ 91.706258] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
> > [ 91.706260] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
> > [ 91.706262] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X
> >
> > The issues appear to be 100% reproducible.
> >
>
> I'm not able to reproduce the issue. Can you specify your kernel version
> and attach your .config?

The kernel is basically 2.6.37-rc6, but I was able to reproduce this with
previous 2.6.37-rc too.

Attached are the full dmesg containing the traces I sent before and .config.

Thanks,
Rafael

Attachments:

2.6.37-rc6.log (115.27 kB)
kernel-config (70.45 kB)
Download all attachments

2010-12-26 19:00:47

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

2010-12-26 22:07:20

by Rafael J. Wysocki

[permalink] [raw]

Subject: Re: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

On Friday, December 17, 2010, Rafael J. Wysocki wrote:
> On Friday, December 17, 2010, Xu, Andiry wrote:
> > >
> > > and during shutdown (I believe the warnings are the same or analogous
> > to
> > > the
> > > above).
> > >
> > > I tested with the attached patch from Andiry applied and I got the
> > > following
> > > BUG during resume:
> >
> > Does this bug occurs without the synchronize irq patch?
>
> Yes, it does.
>
> > Seems the rmmod, shutdown and resume bugs are caused by xhci_cleanup_msix().
> >
> > >
> > > [ 91.703778] sd 0:0:0:0: [sda] Starting disk
> > > [ 91.704054] sd 2:0:0:0: [sdb] Starting disk
> > > [ 91.703680] xhci_hcd 0000:04:00.0: Host controller not halted,
> > aborting
> > > reset.
> > > [ 91.703680] BUG: sleeping function called from invalid context at
> > > /home/rafael/src/linux-2.6/kernel/mutex.c:278
> > > [ 91.703680] in_atomic(): 1, irqs_disabled(): 1, pid: 1234, name:
> > > kworker/u:6
> > > [ 91.703680] INFO: lockdep is turned off.
> > > [ 91.703680] irq event stamp: 24060
> > > [ 91.703680] hardirqs last enabled at (24059): [<ffffffff810aa071>]
> > > rcu_note_context_switch+0xa1/0x1c0
> > > [ 91.703680] hardirqs last disabled at (24060): [<ffffffff81494e92>]
> > > _raw_spin_lock_irq+0x12/0x50
> > > [ 91.703680] softirqs last enabled at (20026): [<ffffffff8105056e>]
> > > __do_softirq+0x11e/0x160
> > > [ 91.703680] softirqs last disabled at (20011): [<ffffffff8100368c>]
> > > call_softirq+0x1c/0x30
> > > [ 91.703680] Pid: 1234, comm: kworker/u:6 Tainted: G W
> > 2.6.37-
> > > rc6+ #12
> > > [ 91.703680] Call Trace:
> > > [ 91.703680] [<ffffffff81079290>] ? print_irqtrace_events+0xd0/0xe0
> > > [ 91.703680] [<ffffffff81036783>] __might_sleep+0x103/0x130
> > > [ 91.703680] [<ffffffff81492f73>] mutex_lock_nested+0x33/0x380
> > > [ 91.703680] [<ffffffff81495727>] ?
> > > _raw_spin_unlock_irqrestore+0x67/0x70
> > > [ 91.703680] [<ffffffff810a39de>] ? dynamic_irq_cleanup+0xde/0x100
> > > [ 91.703680] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
> > > [ 91.703680] [<ffffffff81022008>] destroy_irq+0x78/0x90
> > > [ 91.703680] [<ffffffff810222c9>] native_teardown_msi_irq+0x9/0x10
> > > [ 91.703680] [<ffffffff811ee0b0>]
> > default_teardown_msi_irqs+0x70/0xa0
> > > [ 91.703680] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
> > > [ 91.703680] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
> > > [ 91.703680] [<ffffffffa03f0609>] xhci_cleanup_msix+0x39/0x80
> > [xhci_hcd]
> > > [ 91.703680] [<ffffffffa03f111c>] xhci_resume+0x1ac/0x250
> > [xhci_hcd]
> > > [ 91.703680] [<ffffffffa03f65c4>] xhci_pci_resume+0x14/0x20
> > [xhci_hcd]
> > > [ 91.703680] [<ffffffff8138996b>] resume_common+0xbb/0x140
> > > [ 91.703680] [<ffffffff81389a5e>] hcd_pci_restore+0xe/0x10
> > > [ 91.703680] [<ffffffff811e36f3>] pci_pm_restore+0x63/0xb0
> > > [ 91.703680] [<ffffffff813334bd>] pm_op+0x19d/0x1c0
> > > [ 91.703680] [<ffffffff81333be4>] device_resume+0x94/0x220
> > > [ 91.703680] [<ffffffff81333d8c>] async_resume+0x1c/0x50
> > > [ 91.703680] [<ffffffff8106e6e6>] async_run_entry_fn+0x86/0x160
> > > [ 91.703680] [<ffffffff81060672>] process_one_work+0x1a2/0x450
> > > [ 91.703680] [<ffffffff81060614>] ? process_one_work+0x144/0x450
> > > [ 91.703680] [<ffffffff811d2704>] ? do_raw_spin_lock+0x104/0x170
> > > [ 91.703680] [<ffffffff8106e660>] ? async_run_entry_fn+0x0/0x160
> > > [ 91.703680] [<ffffffff81061e32>] worker_thread+0x162/0x340
> > > [ 91.703680] [<ffffffff81061cd0>] ? worker_thread+0x0/0x340
> > > [ 91.703680] [<ffffffff81066836>] kthread+0x96/0xa0
> > > [ 91.703680] [<ffffffff81003594>] kernel_thread_helper+0x4/0x10
> > > [ 91.703680] [<ffffffff81036fdb>] ? finish_task_switch+0x7b/0xe0
> > > [ 91.703680] [<ffffffff81495d00>] ? restore_args+0x0/0x30
> > > [ 91.703680] [<ffffffff810667a0>] ? kthread+0x0/0xa0
> > > [ 91.703680] [<ffffffff81003590>] ? kernel_thread_helper+0x0/0x10
> > > [ 91.706248] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
> > > [ 91.706251] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
> > > [ 91.706253] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
> > > [ 91.706256] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
> > > [ 91.706258] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
> > > [ 91.706260] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
> > > [ 91.706262] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X
> > >
> > > The issues appear to be 100% reproducible.
> > >
> >
> > I'm not able to reproduce the issue. Can you specify your kernel version
> > and attach your .config?
>
> The kernel is basically 2.6.37-rc6, but I was able to reproduce this with
> previous 2.6.37-rc too.
>
> Attached are the full dmesg containing the traces I sent before and .config.

OK, so the problem seems to be that xhci_cleanup_msix() cannot be called under
a spinlock, because it causes a mutex to be acquired somewhere up the call
chain.

Also, you don't really need to do this "drop MSI-X and acquire a 'normal' IRQ
to fool the USB core" thing during suspend.

The appended patch works on my test machine, where I mean that (a) the reported
warnings don't appear and (b) it doesn't crash the system during resume (from
hibernation).

Thanks,
Rafael

---
drivers/usb/core/hcd-pci.c | 3 ++-
drivers/usb/host/xhci.c | 38 ++++++++------------------------------
include/linux/usb/hcd.h | 1 +
3 files changed, 11 insertions(+), 31 deletions(-)

Index: linux-2.6/include/linux/usb/hcd.h
===================================================================
--- linux-2.6.orig/include/linux/usb/hcd.h
+++ linux-2.6/include/linux/usb/hcd.h
@@ -119,6 +119,7 @@ struct usb_hcd {
unsigned wireless:1; /* Wireless USB HCD */
unsigned authorized_default:1;
unsigned has_tt:1; /* Integrated TT in root hub */
+ unsigned multiple_irqs:1; /* Multiple IRQs used */

int irq; /* irq allocated */
void __iomem *regs; /* device memory/io */
Index: linux-2.6/drivers/usb/core/hcd-pci.c
===================================================================
--- linux-2.6.orig/drivers/usb/core/hcd-pci.c
+++ linux-2.6/drivers/usb/core/hcd-pci.c
@@ -406,7 +406,8 @@ static int suspend_common(struct device
return retval;
}

- synchronize_irq(pci_dev->irq);
+ if (!hcd->multiple_irqs)
+ synchronize_irq(pci_dev->irq);

/* Downstream ports from this root hub should already be quiesced, so
* there will be no DMA activity. Now we can shut down the upstream
Index: linux-2.6/drivers/usb/host/xhci.c
===================================================================
--- linux-2.6.orig/drivers/usb/host/xhci.c
+++ linux-2.6/drivers/usb/host/xhci.c
@@ -263,6 +263,8 @@ static int xhci_setup_msix(struct xhci_h
0, "xhci_hcd", xhci_to_hcd(xhci));
if (ret)
goto disable_msix;
+ else
+ xhci_to_hcd(xhci)->multiple_irqs = true;
}

return ret;
@@ -508,9 +510,10 @@ void xhci_stop(struct usb_hcd *hcd)
spin_lock_irq(&xhci->lock);
xhci_halt(xhci);
xhci_reset(xhci);
- xhci_cleanup_msix(xhci);
spin_unlock_irq(&xhci->lock);

+ xhci_cleanup_msix(xhci);
+
#ifdef CONFIG_USB_XHCI_HCD_DEBUGGING
/* Tell the event ring poll function not to reschedule */
xhci->zombie = 1;
@@ -544,9 +547,10 @@ void xhci_shutdown(struct usb_hcd *hcd)

spin_lock_irq(&xhci->lock);
xhci_halt(xhci);
- xhci_cleanup_msix(xhci);
spin_unlock_irq(&xhci->lock);

+ xhci_cleanup_msix(xhci);
+
xhci_dbg(xhci, "xhci_shutdown completed - status = %x\n",
xhci_readl(xhci, &xhci->op_regs->status));
}
@@ -677,8 +681,6 @@ int xhci_suspend(struct xhci_hcd *xhci)
spin_unlock_irq(&xhci->lock);
return -ETIMEDOUT;
}
- /* step 5: remove core well power */
- xhci_cleanup_msix(xhci);
spin_unlock_irq(&xhci->lock);

return rc;
@@ -694,7 +696,6 @@ int xhci_resume(struct xhci_hcd *xhci, b
{
u32 command, temp = 0;
struct usb_hcd *hcd = xhci_to_hcd(xhci);
- struct pci_dev *pdev = to_pci_dev(hcd->self.controller);
int old_state, retval;

old_state = hcd->state;
@@ -729,9 +730,10 @@ int xhci_resume(struct xhci_hcd *xhci, b
xhci_dbg(xhci, "Stop HCD\n");
xhci_halt(xhci);
xhci_reset(xhci);
+ spin_unlock_irq(&xhci->lock);
+
if (hibernated)
xhci_cleanup_msix(xhci);
- spin_unlock_irq(&xhci->lock);

#ifdef CONFIG_USB_XHCI_HCD_DEBUGGING
/* Tell the event ring poll function not to reschedule */
@@ -765,30 +767,6 @@ int xhci_resume(struct xhci_hcd *xhci, b
return retval;
}

- spin_unlock_irq(&xhci->lock);
- /* Re-setup MSI-X */
- if (hcd->irq)
- free_irq(hcd->irq, hcd);
- hcd->irq = -1;
-
- retval = xhci_setup_msix(xhci);
- if (retval)
- /* fall back to msi*/
- retval = xhci_setup_msi(xhci);
-
- if (retval) {
- /* fall back to legacy interrupt*/
- retval = request_irq(pdev->irq, &usb_hcd_irq, IRQF_SHARED,
- hcd->irq_descr, hcd);
- if (retval) {
- xhci_err(xhci, "request interrupt %d failed\n",
- pdev->irq);
- return retval;
- }
- hcd->irq = pdev->irq;
- }
-
- spin_lock_irq(&xhci->lock);
/* step 4: set Run/Stop bit */
command = xhci_readl(xhci, &xhci->op_regs->command);
command |= CMD_RUN;

2010-12-27 02:36:46

by Andiry Xu

[permalink] [raw]

Subject: RE: Scary warnings from xhci_hcd on rmmod and during shutdown/suspend/resume

> -----Original Message-----
> From: Rafael J. Wysocki [mailto:[email protected]]
> Sent: Monday, December 27, 2010 6:07 AM
> To: Xu, Andiry
> Cc: Sarah Sharp; [email protected];
[email protected];
> Greg Kroah-Hartman; Alan Stern; Linux-pm mailing list; Matthew Garrett
> Subject: Re: Scary warnings from xhci_hcd on rmmod and during
> shutdown/suspend/resume
>
> On Friday, December 17, 2010, Rafael J. Wysocki wrote:
> > On Friday, December 17, 2010, Xu, Andiry wrote:
> > > >
> > > > and during shutdown (I believe the warnings are the same or
> analogous
> > > to
> > > > the
> > > > above).
> > > >
> > > > I tested with the attached patch from Andiry applied and I got
the
> > > > following
> > > > BUG during resume:
> > >
> > > Does this bug occurs without the synchronize irq patch?
> >
> > Yes, it does.
> >
> > > Seems the rmmod, shutdown and resume bugs are caused by
> xhci_cleanup_msix().
> > >
> > > >
> > > > [ 91.703778] sd 0:0:0:0: [sda] Starting disk
> > > > [ 91.704054] sd 2:0:0:0: [sdb] Starting disk
> > > > [ 91.703680] xhci_hcd 0000:04:00.0: Host controller not
halted,
> > > aborting
> > > > reset.
> > > > [ 91.703680] BUG: sleeping function called from invalid
context at
> > > > /home/rafael/src/linux-2.6/kernel/mutex.c:278
> > > > [ 91.703680] in_atomic(): 1, irqs_disabled(): 1, pid: 1234,
name:
> > > > kworker/u:6
> > > > [ 91.703680] INFO: lockdep is turned off.
> > > > [ 91.703680] irq event stamp: 24060
> > > > [ 91.703680] hardirqs last enabled at (24059):
> [<ffffffff810aa071>]
> > > > rcu_note_context_switch+0xa1/0x1c0
> > > > [ 91.703680] hardirqs last disabled at (24060):
> [<ffffffff81494e92>]
> > > > _raw_spin_lock_irq+0x12/0x50
> > > > [ 91.703680] softirqs last enabled at (20026):
> [<ffffffff8105056e>]
> > > > __do_softirq+0x11e/0x160
> > > > [ 91.703680] softirqs last disabled at (20011):
> [<ffffffff8100368c>]
> > > > call_softirq+0x1c/0x30
> > > > [ 91.703680] Pid: 1234, comm: kworker/u:6 Tainted: G W
> > > 2.6.37-
> > > > rc6+ #12
> > > > [ 91.703680] Call Trace:
> > > > [ 91.703680] [<ffffffff81079290>] ?
> print_irqtrace_events+0xd0/0xe0
> > > > [ 91.703680] [<ffffffff81036783>] __might_sleep+0x103/0x130
> > > > [ 91.703680] [<ffffffff81492f73>]
mutex_lock_nested+0x33/0x380
> > > > [ 91.703680] [<ffffffff81495727>] ?
> > > > _raw_spin_unlock_irqrestore+0x67/0x70
> > > > [ 91.703680] [<ffffffff810a39de>] ?
> dynamic_irq_cleanup+0xde/0x100
> > > > [ 91.703680] [<ffffffff810a3a58>] irq_free_descs+0x58/0x90
> > > > [ 91.703680] [<ffffffff81022008>] destroy_irq+0x78/0x90
> > > > [ 91.703680] [<ffffffff810222c9>]
> native_teardown_msi_irq+0x9/0x10
> > > > [ 91.703680] [<ffffffff811ee0b0>]
> > > default_teardown_msi_irqs+0x70/0xa0
> > > > [ 91.703680] [<ffffffff811edb41>] free_msi_irqs+0xa1/0x110
> > > > [ 91.703680] [<ffffffff811eec1d>] pci_disable_msix+0x3d/0x50
> > > > [ 91.703680] [<ffffffffa03f0609>] xhci_cleanup_msix+0x39/0x80
> > > [xhci_hcd]
> > > > [ 91.703680] [<ffffffffa03f111c>] xhci_resume+0x1ac/0x250
> > > [xhci_hcd]
> > > > [ 91.703680] [<ffffffffa03f65c4>] xhci_pci_resume+0x14/0x20
> > > [xhci_hcd]
> > > > [ 91.703680] [<ffffffff8138996b>] resume_common+0xbb/0x140
> > > > [ 91.703680] [<ffffffff81389a5e>] hcd_pci_restore+0xe/0x10
> > > > [ 91.703680] [<ffffffff811e36f3>] pci_pm_restore+0x63/0xb0
> > > > [ 91.703680] [<ffffffff813334bd>] pm_op+0x19d/0x1c0
> > > > [ 91.703680] [<ffffffff81333be4>] device_resume+0x94/0x220
> > > > [ 91.703680] [<ffffffff81333d8c>] async_resume+0x1c/0x50
> > > > [ 91.703680] [<ffffffff8106e6e6>]
async_run_entry_fn+0x86/0x160
> > > > [ 91.703680] [<ffffffff81060672>]
process_one_work+0x1a2/0x450
> > > > [ 91.703680] [<ffffffff81060614>] ?
process_one_work+0x144/0x450
> > > > [ 91.703680] [<ffffffff811d2704>] ?
do_raw_spin_lock+0x104/0x170
> > > > [ 91.703680] [<ffffffff8106e660>] ?
async_run_entry_fn+0x0/0x160
> > > > [ 91.703680] [<ffffffff81061e32>] worker_thread+0x162/0x340
> > > > [ 91.703680] [<ffffffff81061cd0>] ? worker_thread+0x0/0x340
> > > > [ 91.703680] [<ffffffff81066836>] kthread+0x96/0xa0
> > > > [ 91.703680] [<ffffffff81003594>]
kernel_thread_helper+0x4/0x10
> > > > [ 91.703680] [<ffffffff81036fdb>] ?
finish_task_switch+0x7b/0xe0
> > > > [ 91.703680] [<ffffffff81495d00>] ? restore_args+0x0/0x30
> > > > [ 91.703680] [<ffffffff810667a0>] ? kthread+0x0/0xa0
> > > > [ 91.703680] [<ffffffff81003590>] ?
kernel_thread_helper+0x0/0x10
> > > > [ 91.706248] xhci_hcd 0000:04:00.0: irq 81 for MSI/MSI-X
> > > > [ 91.706251] xhci_hcd 0000:04:00.0: irq 82 for MSI/MSI-X
> > > > [ 91.706253] xhci_hcd 0000:04:00.0: irq 83 for MSI/MSI-X
> > > > [ 91.706256] xhci_hcd 0000:04:00.0: irq 84 for MSI/MSI-X
> > > > [ 91.706258] xhci_hcd 0000:04:00.0: irq 85 for MSI/MSI-X
> > > > [ 91.706260] xhci_hcd 0000:04:00.0: irq 86 for MSI/MSI-X
> > > > [ 91.706262] xhci_hcd 0000:04:00.0: irq 87 for MSI/MSI-X
> > > >
> > > > The issues appear to be 100% reproducible.
> > > >
> > >
> > > I'm not able to reproduce the issue. Can you specify your kernel
> version
> > > and attach your .config?
> >
> > The kernel is basically 2.6.37-rc6, but I was able to reproduce this
> with
> > previous 2.6.37-rc too.
> >
> > Attached are the full dmesg containing the traces I sent before
> and .config.
>
> OK, so the problem seems to be that xhci_cleanup_msix() cannot be
called
> under
> a spinlock, because it causes a mutex to be acquired somewhere up the
call
> chain.
>
> Also, you don't really need to do this "drop MSI-X and acquire a
'normal'
> IRQ
> to fool the USB core" thing during suspend.
>
> The appended patch works on my test machine, where I mean that (a) the
> reported
> warnings don't appear and (b) it doesn't crash the system during
resume
> (from
> hibernation).
>

Thanks for the patch. Actually I already have a patch in modification
about synchronize_irq() in xhci_suspend() and I'll submit it later. The
patch will fix your suspend/hibernation issue.

Sarah will submit another patch, move the xhci_cleanup_msix() out of
spinlock to fix the rmmod issue. They are actually two bugs so we use
two patches.

Thanks,
Andiry

> ---
> drivers/usb/core/hcd-pci.c | 3 ++-
> drivers/usb/host/xhci.c | 38
++++++++------------------------------
> include/linux/usb/hcd.h | 1 +
> 3 files changed, 11 insertions(+), 31 deletions(-)
>
> Index: linux-2.6/include/linux/usb/hcd.h
> ===================================================================
> --- linux-2.6.orig/include/linux/usb/hcd.h
> +++ linux-2.6/include/linux/usb/hcd.h
> @@ -119,6 +119,7 @@ struct usb_hcd {
> unsigned wireless:1; /* Wireless USB HCD */
> unsigned authorized_default:1;
> unsigned has_tt:1; /* Integrated TT in root
hub */
> + unsigned multiple_irqs:1; /* Multiple IRQs
used */
>
> int irq; /* irq allocated */
> void __iomem *regs; /* device memory/io */
> Index: linux-2.6/drivers/usb/core/hcd-pci.c
> ===================================================================
> --- linux-2.6.orig/drivers/usb/core/hcd-pci.c
> +++ linux-2.6/drivers/usb/core/hcd-pci.c
> @@ -406,7 +406,8 @@ static int suspend_common(struct device
> return retval;
> }
>
> - synchronize_irq(pci_dev->irq);
> + if (!hcd->multiple_irqs)
> + synchronize_irq(pci_dev->irq);
>
> /* Downstream ports from this root hub should already be
quiesced,
> so
> * there will be no DMA activity. Now we can shut down the
upstream
> Index: linux-2.6/drivers/usb/host/xhci.c
> ===================================================================
> --- linux-2.6.orig/drivers/usb/host/xhci.c
> +++ linux-2.6/drivers/usb/host/xhci.c
> @@ -263,6 +263,8 @@ static int xhci_setup_msix(struct xhci_h
> 0, "xhci_hcd", xhci_to_hcd(xhci));
> if (ret)
> goto disable_msix;
> + else
> + xhci_to_hcd(xhci)->multiple_irqs = true;
> }
>
> return ret;
> @@ -508,9 +510,10 @@ void xhci_stop(struct usb_hcd *hcd)
> spin_lock_irq(&xhci->lock);
> xhci_halt(xhci);
> xhci_reset(xhci);
> - xhci_cleanup_msix(xhci);
> spin_unlock_irq(&xhci->lock);
>
> + xhci_cleanup_msix(xhci);
> +
> #ifdef CONFIG_USB_XHCI_HCD_DEBUGGING
> /* Tell the event ring poll function not to reschedule */
> xhci->zombie = 1;
> @@ -544,9 +547,10 @@ void xhci_shutdown(struct usb_hcd *hcd)
>
> spin_lock_irq(&xhci->lock);
> xhci_halt(xhci);
> - xhci_cleanup_msix(xhci);
> spin_unlock_irq(&xhci->lock);
>
> + xhci_cleanup_msix(xhci);
> +
> xhci_dbg(xhci, "xhci_shutdown completed - status = %x\n",
> xhci_readl(xhci, &xhci->op_regs->status));
> }
> @@ -677,8 +681,6 @@ int xhci_suspend(struct xhci_hcd *xhci)
> spin_unlock_irq(&xhci->lock);
> return -ETIMEDOUT;
> }
> - /* step 5: remove core well power */
> - xhci_cleanup_msix(xhci);
> spin_unlock_irq(&xhci->lock);
>
> return rc;
> @@ -694,7 +696,6 @@ int xhci_resume(struct xhci_hcd *xhci, b
> {
> u32 command, temp = 0;
> struct usb_hcd *hcd = xhci_to_hcd(xhci);
> - struct pci_dev *pdev =
to_pci_dev(hcd->self.controller);
> int old_state, retval;
>
> old_state = hcd->state;
> @@ -729,9 +730,10 @@ int xhci_resume(struct xhci_hcd *xhci, b
> xhci_dbg(xhci, "Stop HCD\n");
> xhci_halt(xhci);
> xhci_reset(xhci);
> + spin_unlock_irq(&xhci->lock);
> +
> if (hibernated)
> xhci_cleanup_msix(xhci);
> - spin_unlock_irq(&xhci->lock);
>
> #ifdef CONFIG_USB_XHCI_HCD_DEBUGGING
> /* Tell the event ring poll function not to reschedule
*/
> @@ -765,30 +767,6 @@ int xhci_resume(struct xhci_hcd *xhci, b
> return retval;
> }
>
> - spin_unlock_irq(&xhci->lock);
> - /* Re-setup MSI-X */
> - if (hcd->irq)
> - free_irq(hcd->irq, hcd);
> - hcd->irq = -1;
> -
> - retval = xhci_setup_msix(xhci);
> - if (retval)
> - /* fall back to msi*/
> - retval = xhci_setup_msi(xhci);
> -
> - if (retval) {
> - /* fall back to legacy interrupt*/
> - retval = request_irq(pdev->irq, &usb_hcd_irq,
IRQF_SHARED,
> - hcd->irq_descr, hcd);
> - if (retval) {
> - xhci_err(xhci, "request interrupt %d failed\n",
> - pdev->irq);
> - return retval;
> - }
> - hcd->irq = pdev->irq;
> - }
> -
> - spin_lock_irq(&xhci->lock);
> /* step 4: set Run/Stop bit */
> command = xhci_readl(xhci, &xhci->op_regs->command);
> command |= CMD_RUN;