Kernel v4.3 - RCU hang, USB implicated

[Ilia Mirkin]

Hello all,

I'm not sure if USB hung because RCU died, or actually caused the RCU
death itself. Hopefully the below is useful in determining the issue.
I have a pretty standard system with a Haswell i7-4790 CPU, and these
USB controllers:

00:14.0 USB controller [0c03]: Intel Corporation 8 Series/C220 Series
Chipset Family USB xHCI [8086:8c31] (rev 05)
00:1a.0 USB controller [0c03]: Intel Corporation 8 Series/C220 Series
Chipset Family USB EHCI #2 [8086:8c2d] (rev 05)
00:1d.0 USB controller [0c03]: Intel Corporation 8 Series/C220 Series
Chipset Family USB EHCI #1 [8086:8c26] (rev 05)

The below spew kept going ad-infinitum with increasing jiffies counts
until I reset the box (it wouldn't wake up to local input, although
since that's USB, not too surprising in hindsight). I suspect it might
have been triggered by my monitors going to sleep, which in turn
disconnects the USB hub within, to which my mouse is connected. (I
found out that hooking the keyboard up to those wasn't smart... my
bootloader tends to freak out.)

Please let me know if there's any additional relevant info I can
provide. I haven't been running v4.3 long, but this is the first time
this happened. The kernel I ran earlier, v4.0.5, never produced such
errors (that I know about).

[Not particularly thrilled about the \x09 in there either...]

Thanks,

  -ilia

INFO: rcu_sched detected stalls on CPUs/tasks:
\x090: (5 GPs behind) idle=885/1/0 softirq=2623140/2623141 fqs=6990
\x09(detected by 7, t=21002 jiffies, g=3598337, c=3598336, q=6721)
Task dump for CPU 0:
swapper/0       R  running task    14624     0      0 0x00000008
 0000000000000018 00003d6348081d6c 0000243081e03f18 ffffffff81ebcab8
 ffffffff81f39d18 ffffffff81e04000 ffff88022fa1d618 ffffffff81ebc8c0
 ffffffff81e00000 ffffffff81e03f10 ffffffff816cc0e7 ffffffff81e03f28
Call Trace:
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff818b8777>] ? rest_init+0x77/0x80
 [<ffffffff81f5eebb>] ? start_kernel+0x43c/0x449
 [<ffffffff81f5e495>] ? x86_64_start_reservations+0x2a/0x2c
 [<ffffffff81f5e582>] ? x86_64_start_kernel+0xeb/0xee
xhci_hcd 0000:00:14.0: xHCI host not responding to stop endpoint command.
xhci_hcd 0000:00:14.0: Assuming host is dying, halting host.
xhci_hcd 0000:00:14.0: HC died; cleaning up
usb 1-7: USB disconnect, device number 2
usb 2-4: USB disconnect, device number 2
usb 2-4.4: USB disconnect, device number 3
INFO: rcu_sched detected expedited stalls on CPUs: { 0 2 4 5 6 7 }
21000 jiffies s: 565
Task dump for CPU 0:
swapper/0       R  running task    14624     0      0 0x00000008
 0000000000000018 00003d6348081d6c 0000243081e03f18 ffffffff81ebcab8
 ffffffff81f39d18 ffffffff81e04000 ffff88022fa1d618 ffffffff81ebc8c0
 ffffffff81e00000 ffffffff81e03f10 ffffffff816cc0e7 ffffffff81e03f28
Call Trace:
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff818b8777>] ? rest_init+0x77/0x80
 [<ffffffff81f5eebb>] ? start_kernel+0x43c/0x449
 [<ffffffff81f5e495>] ? x86_64_start_reservations+0x2a/0x2c
 [<ffffffff81f5e582>] ? x86_64_start_kernel+0xeb/0xee
Task dump for CPU 2:
kworker/2:2     R  running task    13152 23226      2 0x00000000
Workqueue: usb_hub_wq hub_event
 ffff88017fd3ba08 ffff88017fd3b9c8 ffffffff8111dfc8 0000000000000002
 ffff88017fd3ba08 ffff88017fd3b9e0 ffffffff8111fd39 0000000000000002
 ffff88017fd3ba30 ffffffff81146727 ffff880100000000 ffff880225e62580
Call Trace:
 [<ffffffff8111dfc8>] sched_show_task+0xc8/0x130
 [<ffffffff8111fd39>] dump_cpu_task+0x39/0x40
 [<ffffffff81146727>] synchronize_sched_expedited_wait.constprop.64+0x1f7/0x220
 [<ffffffff8112d420>] ? wait_woken+0x80/0x80
 [<ffffffff81146945>] synchronize_sched_expedited+0x1f5/0x2e0
 [<ffffffff81146a3e>] synchronize_rcu_expedited+0xe/0x10
 [<ffffffff811c8eaf>] bdi_unregister+0x4f/0x100
 [<ffffffff813a6fff>] blk_cleanup_queue+0xef/0x120
 [<ffffffff815c79b4>] __scsi_remove_device+0x54/0xd0
 [<ffffffff815c6060>] scsi_forget_host+0x60/0x70
 [<ffffffff815bb947>] scsi_remove_host+0x77/0x110
 [<ffffffff81661629>] usb_stor_disconnect+0x59/0xc0
 [<ffffffff8162c723>] usb_unbind_interface+0x83/0x270
 [<ffffffff8159a8e6>] __device_release_driver+0x96/0x130
 [<ffffffff8159a9a3>] device_release_driver+0x23/0x30
 [<ffffffff81599a88>] bus_remove_device+0xf8/0x140
 [<ffffffff81596499>] device_del+0x139/0x270
 [<ffffffff81630c1f>] ? usb_remove_ep_devs+0x1f/0x30
 [<ffffffff8162a270>] usb_disable_device+0xa0/0x1f0
 [<ffffffff81621767>] usb_disconnect+0x87/0x230
 [<ffffffff8162196a>] hub_quiesce+0x5a/0xb0
 [<ffffffff8162310f>] hub_event+0x33f/0x1180
 [<ffffffff81127731>] ? pick_next_task_fair+0xa1/0x970
 [<ffffffff8110dd2c>] process_one_work+0x14c/0x3d0
 [<ffffffff8110e2cb>] worker_thread+0x4b/0x440
 [<ffffffff818b9f15>] ? __schedule+0x335/0x8e0
 [<ffffffff8110e280>] ? rescuer_thread+0x2d0/0x2d0
 [<ffffffff8110e280>] ? rescuer_thread+0x2d0/0x2d0
 [<ffffffff81112e39>] kthread+0xc9/0xe0
 [<ffffffff81112d70>] ? kthread_park+0x60/0x60
 [<ffffffff818be1af>] ret_from_fork+0x3f/0x70
 [<ffffffff81112d70>] ? kthread_park+0x60/0x60
Task dump for CPU 4:
swapper/4       R  running task    15136     0      1 0x00200000
 ffffffff816cbf54 00003d757e834a8c 0000034026a5fec8 ffffffff81ebcab8
 ffffffff81f39d18 ffff880226a60000 ffff88022fb1d618 ffffffff81ebc8c0
 ffff880226a5c000 ffff880226a5fec0 ffffffff816cc0e7 ffff880226a5fed8
Call Trace:
 [<ffffffff816cbf54>] ? cpuidle_enter_state+0xb4/0x210
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff8107e92c>] ? start_secondary+0x12c/0x140
Task dump for CPU 5:
swapper/5       R  running task    15136     0      1 0x00200000
 ffffffff816cbf54 00003d757e839c17 0000033d26a63ec8 ffffffff81ebcab8
 ffffffff81f39d18 ffff880226a64000 ffff88022fb5d618 ffffffff81ebc8c0
 ffff880226a60000 ffff880226a63ec0 ffffffff816cc0e7 ffff880226a63ed8
Call Trace:
 [<ffffffff816cbf54>] ? cpuidle_enter_state+0xb4/0x210
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff8107e92c>] ? start_secondary+0x12c/0x140
Task dump for CPU 6:
swapper/6       R  running task    15136     0      1 0x00200000
 ffffffff816cbf54 00003d757e83a003 0000033d26a67ec8 ffffffff81ebcab8
 ffffffff81f39d18 ffff880226a68000 ffff88022fb9d618 ffffffff81ebc8c0
 ffff880226a64000 ffff880226a67ec0 ffffffff816cc0e7 ffff880226a67ed8
Call Trace:
 [<ffffffff816cbf54>] ? cpuidle_enter_state+0xb4/0x210
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff8107e92c>] ? start_secondary+0x12c/0x140
Task dump for CPU 7:
swapper/7       R  running task    15136     0      1 0x00200000
 ffffffff816cbf54 00003d757e839c21 0000033d26a6bec8 ffffffff81ebcab8
 ffffffff81f39d18 ffff880226a6c000 ffff88022fbdd618 ffffffff81ebc8c0
 ffff880226a68000 ffff880226a6bec0 ffffffff816cc0e7 ffff880226a6bed8
Call Trace:
 [<ffffffff816cbf54>] ? cpuidle_enter_state+0xb4/0x210
 [<ffffffff816cc0e7>] ? cpuidle_enter+0x17/0x20
 [<ffffffff8112d842>] ? call_cpuidle+0x32/0x60
 [<ffffffff816cc0c3>] ? cpuidle_select+0x13/0x20
 [<ffffffff8112dab3>] ? cpu_startup_entry+0x243/0x2f0
 [<ffffffff8107e92c>] ? start_secondary+0x12c/0x140
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/