usb: dwc2: NMI watchdog: BUG: soft lockup - CPU#0 stuck for 146s

[Stefan Wahren]

I inspired by this issue [1] i build up a slightly modified setup with a
Raspberry Pi B (mainline kernel 4.9rc3), a powered 7 port USB hub and 5 Prolific
PL2303 USB to serial convertors. I modified the usb_test for dwc2 [2], which
only tries to open all ttyUSB devices one after the other. 

Unfortunately the complete system stuck after opening the first ttyUSB device (
heartbeat LED stop blinking, no reaction to debug UART). The only way to
reanimate the system is to powerdown the USB hub with the USB to serial
convertors.

[1] - https://github.com/raspberrypi/linux/issues/1692
[2] - https://gist.github.com/lategoodbye/dd0d30af27b6f101b03d5923b279dbaa

pi at raspberrypi:~$ lsusb -t
/:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=dwc2/1p, 480M
    |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/3p, 480M
        |__ Port 1: Dev 3, If 0, Class=Vendor Specific Class, Driver=smsc95xx,
480M
        |__ Port 2: Dev 11, If 0, Class=Hub, Driver=hub/4p, 480M
            |__ Port 3: Dev 15, If 0, Class=Vendor Specific Class,
Driver=pl2303, 12M
            |__ Port 1: Dev 12, If 0, Class=Hub, Driver=hub/4p, 480M
                |__ Port 2: Dev 14, If 0, Class=Vendor Specific Class,
Driver=pl2303, 12M
                |__ Port 3: Dev 16, If 0, Class=Vendor Specific Class,
Driver=pl2303, 12M
            |__ Port 4: Dev 17, If 0, Class=Vendor Specific Class,
Driver=pl2303, 12M
            |__ Port 2: Dev 13, If 0, Class=Vendor Specific Class,
Driver=pl2303, 12M

pi at raspberrypi:~$ ./usb_test
idle
opening [/dev/ttyUSB0] ok
[  232.658768] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 146s!
[usb_test:522]
[  232.678443] Modules linked in: pwm_bcm2835 vchiq(C)
[  232.678481] CPU: 0 PID: 522 Comm: usb_test Tainted: G         C
     4.9.0-rc3+ #33
[  232.678486] Hardware name: BCM2835
[  232.678498] task: cab54e40 task.stack: c688c000
[  232.678520] PC is at __do_softirq+0x68/0x2a8
[  232.678538] LR is at irq_exit+0xb8/0x120
[  232.678552] pc : [<c01014d0>]    lr : [<c0121270>]    psr: 60000113
sp : c688da60  ip : c688daa8  fp : c688daa4
[  232.678560] r10: c0b7f800  r9 : c688c000  r8 : 00400000
[  232.678567] r7 : 0000000a  r6 : cb802400  r5 : 00000000  r4 : 00000001
[  232.678575] r3 : 00000000  r2 : 00000100  r1 : 00400000  r0 : 00000000
[  232.678585] Flags: nZCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[  232.678593] Control: 00c5387d  Table: 068a4008  DAC: 00000051
[  232.678604] CPU: 0 PID: 522 Comm: usb_test Tainted: G         C
     4.9.0-rc3+ #33
[  232.678609] Hardware name: BCM2835
[  232.678667] [<c010ecc0>] (unwind_backtrace) from [<c010bc28>]
(show_stack+0x20/0x24)
[  232.678695] [<c010bc28>] (show_stack) from [<c03684e0>]
(dump_stack+0x20/0x28)
[  232.678718] [<c03684e0>] (dump_stack) from [<c0108ee4>] (show_regs+0x1c/0x20)
[  232.678752] [<c0108ee4>] (show_regs) from [<c018ea00>]
(watchdog_timer_fn+0x140/0x19c)
[  232.678779] [<c018ea00>] (watchdog_timer_fn) from [<c015eefc>]
(__hrtimer_run_queues.constprop.3+0xec/0x210)
[  232.678798] [<c015eefc>] (__hrtimer_run_queues.constprop.3) from [<c015f210>]
(hrtimer_interrupt+0xa4/0x1cc)
[  232.678827] [<c015f210>] (hrtimer_interrupt) from [<c04eff58>]
(bcm2835_time_interrupt+0x40/0x48)
[  232.678865] [<c04eff58>] (bcm2835_time_interrupt) from [<c01537ec>]
(__handle_irq_event_percpu+0x68/0x1b8)
[  232.678891] [<c01537ec>] (__handle_irq_event_percpu) from [<c0153968>]
(handle_irq_event_percpu+0x2c/0x68)
[  232.678915] [<c0153968>] (handle_irq_event_percpu) from [<c01539dc>]
(handle_irq_event+0x38/0x4c)
[  232.678939] [<c01539dc>] (handle_irq_event) from [<c0156df8>]
(handle_level_irq+0xc4/0xf8)
[  232.678960] [<c0156df8>] (handle_level_irq) from [<c0152fd8>]
(generic_handle_irq+0x28/0x38)
[  232.678983] [<c0152fd8>] (generic_handle_irq) from [<c0153144>]
(__handle_domain_irq+0x90/0xb8)
[  232.679004] [<c0153144>] (__handle_domain_irq) from [<c01013f4>]
(bcm2835_handle_irq+0x30/0x48)
[  232.679022] [<c01013f4>] (bcm2835_handle_irq) from [<c010c7cc>]
(__irq_svc+0x6c/0x90)
[  232.679031] Exception stack(0xc688da10 to 0xc688da58)
[  232.679044] da00:                                     00000000 00400000
00000100 00000000
[  232.679062] da20: 00000001 00000000 cb802400 0000000a 00400000 c688c000
c0b7f800 c688daa4
[  232.679078] da40: c688daa8 c688da60 c0121270 c01014d0 60000113 fffff000000
c687a300 c9374900 ca918b00 caff1200 c688db84
[  232.679235] db20: c688db28 c688db40 c04a1cf8 c049cb64 60000013 ffffffff
[  232.679272] [<c010c7cc>] (__irq_svc) from [<c049cb64>]
(_dwc2_hcd_urb_enqueue+0x414/0x560)
[  232.679302] [<c049cb64>] (_dwc2_hcd_urb_enqueue) from [<c04849ac>]
(usb_hcd_submit_urb+0x704/0x8c4)
[  232.679327] [<c04849ac>] (usb_hcd_submit_urb) from [<c048628c>]
(usb_submit_urb+0x438/0x4e0)
[  232.679358] [<c048628c>] (usb_submit_urb) from [<c04a9d60>]
(usb_serial_generic_submit_read_urb+0x50/0xc8)
[  232.679382] [<c04a9d60>] (usb_serial_generic_submit_read_urb) from
[<c04aa0a8>] (usb_serial_generic_submit_read_urbs+0x28/0x70)
[  232.679407] [<c04aa0a8>] (usb_serial_generic_submit_read_urbs) from
[<c04aa298>] (usb_serial_generic_open+0x44/0x4c)
[  232.679435] [<c04aa298>] (usb_serial_generic_open) from [<c04aebc4>]
(pl2303_open+0xc0/0xe0)
[  232.679458] [<c04aebc4>] (pl2303_open) from [<c04a744c>]
(serial_port_activate+0x54/0x8c)
[  232.679486] [<c04a744c>] (serial_port_activate) from [<c03c4014>]
(tty_port_open+0x84/0xd4)
[  232.679509] [<c03c4014>] (tty_port_open) from [<c04a7d40>]
(serial_open+0x34/0x5c)
[  232.679546] [<c04a7d40>] (serial_open) from [<c03bd3a8>]
(tty_open+0x380/0x534)
[  232.679578] [<c03bd3a8>] (tty_open) from [<c021e188>]
(chrdev_open+0x120/0x14c)
[  232.679612] [<c021e188>] (chrdev_open) from [<c0217368>]
(do_dentry_open+0x1b8/0x304)
[  232.679638] [<c0217368>] (do_dentry_open) from [<c021876c>]
(vfs_open+0x7c/0x80)
[  232.679663] [<c021876c>] (vfs_open) from [<c022834c>]
(path_openat+0xb60/0xd88)
[  232.679682] [<c022834c>] (path_openat) from [<c02285bc>]
(do_filp_open+0x48/0x94)
[  232.679704] [<c02285bc>] (do_filp_open) from [<c0218af4>]
(do_sys_open+0x12c/0x1cc)
[  232.679728] [<c0218af4>] (do_sys_open) from [<c0218bc4>] (SyS_open+0x30/0x34)
[  232.679754] [<c0218bc4>] (SyS_open) from [<c0108280>]
(ret_fast_syscall+0x0/0x3c)
[  233.852571] usb 1-1.2: clear tt 1 (9063) error -110
[  233.853046] usb 1-1.2.1: clear tt 1 (9073) error -110
[  234.892554] usb 1-1.2.1: clear tt 1 (9071) error -110
[  234.892995] usb 1-1.2: clear tt 1 (9061) error -110
[  235.932574] usb 1-1.2.1: clear tt 1 (9073) error -110
[  235.933542] usb 1-1.2: clear tt 1 (9063) error -110
[  236.972595] usb 1-1.2.1: clear tt 1 (9071) error -110
[  236.973235] usb 1-1.2: clear tt 1 (9061) error -110
[  238.012573] usb 1-1.2: clear tt 1 (9063) error -110
[  238.013052] usb 1-1.2.1: clear tt 1 (9073) error -110
[  238.013456] hub 1-1:1.0: hub_ext_port_status failed (err = -110)
[  239.052567] usb 1-1.2.1: clear tt 1 (9071) error -110
[  239.053076] usb 1-1.2: clear tt 1 (9061) error -110
[  240.092573] usb 1-1.2: clear tt 1 (9063) error -110
[  240.093050] usb 1-1.2.1: clear tt 1 (9073) error -110
[  240.239643] usb 1-1.2.1: USB disconnect, device number 5
[  240.239685] usb 1-1.2.1.2: USB disconnect, device number 7
[  240.262707] usb 1-1.2: clear tt 1 (9061) error -71
[  240.263123] usb 1-1.2.1: clear tt 1 (9071) error -71
[  240.263708] usb 1-1.2: USB disconnect, device number 4
[  694304] pl2303 ttyUSB0: pl2303 converter now disconnected from ttyUSB0
[  251.694645] pl2303 1-1.2.2:1.0: device disconnected
[  251.704668] usb 1-1.2.3: USB disconnect, device number 8
[  251.706468] pl2303 ttyUSB2: pl2303 converter now disconnected from ttyUSB2
[  251.706894] pl2303 1-1.2.3:1.0: device disconnected
[  251.714720] usb 1-1.2.4: USB disconnect, device number 10
[  251.733019] pl2303 ttyUSB4: pl2303 converter now disconnected from ttyUSB4
[  251.733459] pl2303 1-1.2.4:1.0: device disconnected
[  251.852767] hub 1-1.2:1.0: activate --> -19