[Bug 221103] xhci_hcd: System lockup under CPU load during usbfs polling of USB devices on AMD platforms

[bugzilla-daemon@kernel.org]

https://bugzilla.kernel.org/show_bug.cgi?id=221103

--- Comment #40 from Andrew Skalski (voltara@gmail.com) ---
(In reply to Michał Pecio from comment #38)
> It's theoretically possible that the crash happens when the xHC is resumed
> too quickly after being suspended. Maybe it doesn't matter how long we keep
> it awake, until this duration is so long that immediately after suspending
> some userspace loop enters another iteration and resumes it back.

After experimenting more, I'm starting to think that it's actually the other
way around: Suspending the device at the "wrong" time causes the next resume to
crash.

I wrote a program that opens "/dev/bus/usb/002/001" and alternately writes
"on\n" and "auto\n" on a predetermined schedule.  For the timing, I use
clock_nanosleep(CLOCK_MONOTONIC, TIMER_ABSTIME, &ts) to control for drift due
to waiting for the IO to complete.

On my system, I found the sweet spot to be around 240700us between initiating
write("on\n") and write("auto\n").  Example output leading to a crash on a 7.0
kernel without your patch:

$ sudo ./a.out 
+3000000 us resume, +240722 us autosuspend: ..........R..........S
+3000000 us resume, +240694 us autosuspend: ..........R..........S
+3000000 us resume, +240701 us autosuspend: ..........R..........S
+3000000 us resume, +240703 us autosuspend: ..........R..........S
+3000000 us resume, +240714 us autosuspend: ..........R..........S
+3000000 us resume, +240698 us autosuspend: ..........

The dots are printed in a { print '.', sleep 1/10 of the duration } loop.
The "R" and "S" are printed after the write("on\n") and write("auto\n") return.

While I ran the above program, I set these dynamic_debug flags and captured
dmesg output.  (First column is the time difference from the previous log
message.)

module xhci_hcd func xhci_suspend +ptmfl
module xhci_hcd func xhci_resume +ptmfl

30.404398 [ 1135.752405] [7530] xhci_hcd:xhci_resume:1282: xhci_hcd
0000:e4:00.4: xhci_resume: starting usb1 port polling.
0.227738 [ 1135.980143] [6986] xhci_hcd:xhci_suspend:993: xhci_hcd
0000:e4:00.4: xhci_suspend: stopping usb1 port polling.
3.012930 [ 1138.993073] [7530] xhci_hcd:xhci_resume:1282: xhci_hcd
0000:e4:00.4: xhci_resume: starting usb1 port polling.
0.227758 [ 1139.220831] [6986] xhci_hcd:xhci_suspend:993: xhci_hcd
0000:e4:00.4: xhci_suspend: stopping usb1 port polling.
3.013086 [ 1142.233917] [7530] xhci_hcd:xhci_resume:1282: xhci_hcd
0000:e4:00.4: xhci_resume: starting usb1 port polling.
0.227617 [ 1142.461534] [798] xhci_hcd:xhci_suspend:993: xhci_hcd 0000:e4:00.4:
xhci_suspend: stopping usb1 port polling.
3.012995 [ 1145.474529] [7530] xhci_hcd:xhci_resume:1282: xhci_hcd
0000:e4:00.4: xhci_resume: starting usb1 port polling.
0.227667 [ 1145.702196] [798] xhci_hcd:xhci_suspend:993: xhci_hcd 0000:e4:00.4:
xhci_suspend: stopping usb1 port polling.
3.012959 [ 1148.715155] [7530] xhci_hcd:xhci_resume:1282: xhci_hcd
0000:e4:00.4: xhci_resume: starting usb1 port polling.
0.227710 [ 1148.942865] [798] xhci_hcd:xhci_suspend:993: xhci_hcd 0000:e4:00.4:
xhci_suspend: stopping usb1 port polling.

I've found that the amount of time spent suspended doesn't matter at all (so
it's not resuming "too quickly".)  However it is very sensitive to the "on"
time.  I haven't tested the full range of wait times, so I don't know if the
above test represents the only danger zone.  But in my testing, suspending the
device sooner is fine.  Suspending it later is fine, but suspending it at that
exact time is problematic - it "feels like" a race condition to me.

-- 
You may reply to this email to add a comment.

You are receiving this mail because:
You are watching the assignee of the bug.