New: usb_storage connected SD card disconnects/reconnects on resume from suspend

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

Bug ID: 220491
Summary: usb_storage connected SD card disconnects/reconnects
on resume from suspend
Product: Drivers
Version: 2.5
Hardware: Intel
OS: Linux
Status: NEW
Severity: normal
Priority: P3
Component: USB
Assignee: [email protected]
Reporter: [email protected]
Regression: No

Created attachment 308549
--> https://bugzilla.kernel.org/attachment.cgi?id=308549&action=edit
This is machine specific to a Samsung Ativ9 laptop, Intel Broadwell platform

I've had this Samsung laptop since 2015, 2560x1600 display, Intel Broadwell platform, battery still has > 5 hour useful life. This is one of two machine specific suspend/resume related problems that I would really like to patch if possible. If the laptop is suspended for a while, the mounted usb connected SD card is unmounted on resume. This results from the associated usb_storage device disconnecting and reconnecting. I've looked at the so-called usb_persist feature and the problem is "hard" enough that the persist feature won't paste over it. I've attached a dmesg log with xhci_hcd dynamic debug enabled. The debug messages are opaque enough that I thought I'd post here on the hope that someone more experienced would weigh in. I am willing to do work but it would be more efficient if I didn't have to discover too much arcana. For instance, the xhci_hcd dynamic debug information doesn't shed much immediate light on why the usb disconnect is happening. I mean there's a lot of xhci logging leading up to the disconnect but it's not immediately clear why the disconnect happens exactly when it happens. Of course, any help would be greatly appreciated.

You may reply to this email to add a comment.

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

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

--- Comment #1 from Paul Ausbeck ([email protected]) --- The affected SD card is in the laptop's internal USB card reader. If I could patch around this problem I could use the SD card as a second flash drive, albeit slower than the ata connected drive, but adequate for media files.

You may reply to this email to add a comment.

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

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

Oliver Neukum ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #2 from Oliver Neukum ([email protected]) --- For the record:

The issue is not with UAS, but at the XHCI layer.

You may reply to this email to add a comment.

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

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

--- Comment #3 from Paul Ausbeck ([email protected]) --- The problem is related to a usb_storage device, not uas. This particular SD card reader has a USB 3.0 interface but only provides about 18MB/s throughput from the SD card. From what I have seen, this is quite typical of laptop internal SD card readers.

You may reply to this email to add a comment.

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

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

--- Comment #4 from Alan Stern ([email protected]) --- You should collect a usbmon trace showing what happens during a suspend and subsequent resume. It might turn out to be a lot more useful than the xHCI dynamic debugging.

You may reply to this email to add a comment.

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

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

--- Comment #5 from Paul Ausbeck ([email protected]) --- Created attachment 308551
--> https://bugzilla.kernel.org/attachment.cgi?id=308551&action=edit
usbmon trace of usb activity during suspend/resume as requested

This usbmon trace includes only the 3.0/5Gb xhci host controller activity. The machine has two other host controllers, one ehci and another xhci/2.0/480Mb. Personally, I find this trace even more opaque than the xhci dynamic_debug output. Hopefully a specialist can find something interesting/relevant.

You may reply to this email to add a comment.

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

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

--- Comment #6 from Alan Stern ([email protected]) ---
The usbmon trace is opaque to people who aren't familiar with the USB protocol, but to people who are, it's a trove of information.

The trace initially shows the card reader getting suspended. Then during the resume it shows that the connection was dropped during the suspend (possibly because the device wasn't powered). The device gets reset okay, but then things start to go wrong at this point:

ffff9bbf9f9de0c0 215868796 S Co:3:003:0 s 00 03 0031 0000 0000 0 ffff9bbf9f9de0c0 215872346 C Co:3:003:0 -71 0 ffff9bbf9f9de0c0 215872402 S Co:3:001:0 s 23 03 0018 0004 0000 0 ffff9bbf9f9de0c0 215872413 C Co:3:001:0 0 0 ffff9bbf9f9de0c0 215872539 S Co:3:003:0 s 00 03 0032 0000 0000 0 ffff9bbf9f9de0c0 220976339 C Co:3:003:0 -2 0

The first two lines show the computer telling the device to enable the U2 low-power link state and the device not replying. The last two lines show the computer telling the device to enable Latency Tolerance Messages (a part of Link Power Management) and the device not acknowledging.

This strongly suggests that the device can't handle LPM properly, and it might start working if you tell the kernel not to use LPM with the device. You can do this by adding a parameter to the kernel's boot command line:

... usbcore.quirks=05e3:0747:k

where 05e3 and 0747 are the card reader's vendor and product IDs, and 'k' is the code letter for "No LPM".

You may reply to this email to add a comment.

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

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

--- Comment #7 from Paul Ausbeck ([email protected]) --- Alan, thank you for interpreting my usbmon trace. I tried your suggested quirk but it had no effect on the objectionable symptom, usb disconnect/reconnect of the usb_storage device. If it would be helpful, I can do some more work and supply a new usbmon trace with the quirk in place.

You may reply to this email to add a comment.

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

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

--- Comment #8 from Oliver Neukum ([email protected]) --- (In reply to Paul Ausbeck from comment #7)

Please do so.

You may reply to this email to add a comment.

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

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

--- Comment #9 from Paul Ausbeck ([email protected]) --- Created attachment 308565
--> https://bugzilla.kernel.org/attachment.cgi?id=308565&action=edit
usbmon trace of successful suspend/resume

The internal usb_storage device does not always disconnect/reconnect on resume from suspend. I have attached a usbmon trace from a successful suspend/resume in that the usb_storage device is merely reset and the associated filesystem remains mounted. This trace has the "k" quirk in place:

[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-6.12.38+deb13-amd64
root=UUID=678480bb-2d48-4a21-bdd3-d13f4a8d21ad ro net.ifnames=0
usbcore.autosuspend=-1 mitigations=off usbcore.quirks=05e3:0747:k quiet
[    0.030419] Kernel command line:
BOOT_IMAGE=/boot/vmlinuz-6.12.38+deb13-amd64
root=UUID=678480bb-2d48-4a21-bdd3-d13f4a8d21ad ro net.ifnames=0
usbcore.autosuspend=-1 mitigations=off usbcore.quirks=05e3:0747:k quiet
[    0.909039] xhci_hcd 0000:00:14.0: hcc params 0x200077c1 hci version 0x100

quirks 0x000000000004b810

You may reply to this email to add a comment.

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

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

--- Comment #10 from Paul Ausbeck ([email protected]) --- Oh, I forgot to mention that I have a USB connected m.2 SATA drive that I also had plugged into a USB Type A port during the last usbmon run. This m.2 drive is a uas device, not usb_storage. The USB connected m.2 device does not suffer from the same problem as the internal USB connected SD card. It always survives suspend/resume without disconnect/reconnect.

Perhaps it was a mistake to have this extra device connected during my last usbmon run as it may make the trace more difficult to analyze. I will continue to trace, without the external drive uas drive, until I again get a disconnect trace with the "k" quirk in place. If it would be useful to provide a reset trace without the external USB device plugged in, let me know.

You may reply to this email to add a comment.

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

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

--- Comment #11 from Paul Ausbeck ([email protected]) --- Created attachment 308566
--> https://bugzilla.kernel.org/attachment.cgi?id=308566&action=edit
usbmon trace, S/R, "k" quirk enabled, usb_storage disconnect/reconnect

This is a usbmon trace of suspend/resume with associated disconnect/reconnect of the internal usb_storage device. The "k" quirk is enabled during this trace.

You may reply to this email to add a comment.

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

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

--- Comment #12 from Alan Stern ([email protected]) --- Okay, this is different from before. Here's a comparison of the relevant parts (referring only to the messages for the card reader).

The difference first appears when the device is reset following the resume and the computer reads the upstream USB port status. From the trace you originally attached (where the reset worked but the device failed later because of LPM):

ffff9bbf9f9de0c0 215792020 S Ci:3:001:0 s a3 00 0000 0004 0004 4 < ffff9bbf9f9de0c0 215792047 C Ci:3:001:0 0 4 = 03021000

That 03021000 is a normal response; it means the port is powered, connected, and enabled, and the reset has completed.

From the trace with LPM disabled but where the resume failed:

ffff8d32e6d06780 1883092024 S Ci:3:001:0 s a3 00 0000 0004 0004 4 < ffff8d32e6d06780 1883092046 C Ci:3:001:0 0 4 = d0024100 ffff8d32e6d06780 1883156157 S Ci:3:001:0 s a3 00 0000 0004 0004 4 < ffff8d32e6d06780 1883156182 C Ci:3:001:0 0 4 = 03025100

The Get-Port-Status request was issued twice. The first response indicates a vendor-specific link status (I guess it was some sort of intermediate state) and the second response shows the final result of the reset. 03025100 is not normal; it means that the port is powered, connected, and enabled (as before), but in addition to the completed reset there was a connect status change and a link-state change -- not surprising given the first response.

This indicates the card reader disconnected and reconnected while the reset was taking place -- a rather peculiar thing for it to do. But I'm puzzled; at this point the kernel should have tried to reset the device again. Instead it continued on.

We can see what happens next. The kernel tries to get the card reader's device descriptor. In the first trace this works, even though there's a useless intervening Set-Isochronous-Delay (in the third and fourth lines):

ffff9bbf9f9de0c0 215864163 S Ci:3:003:0 s 80 06 0100 0000 0008 8 < ffff9bbf9f9de0c0 215864376 C Ci:3:003:0 0 8 = 12010003 00000009 ffff9bbf9f9de0c0 215864472 S Co:3:003:0 s 00 31 0028 0000 0000 0 ffff9bbf9f9de0c0 215864766 C Co:3:003:0 0 0
ffff9bbf9f9de0c0 215864862 S Ci:3:003:0 s 80 06 0100 0000 0012 18 < ffff9bbf9f9de0c0 215865180 C Ci:3:003:0 0 18 = 12010003 00000009 e3054707 19080304 0501

In the other trace, the Get-Device-Descriptor request fails completely, many times:

ffff8d32e6d06180 1883228171 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883228194 E Ci:3:005:0 -19 0 ffff8d32e6d06180 1883228195 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883228209 E Ci:3:005:0 -19 0 ffff8d32e6d06180 1883228210 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883228215 E Ci:3:005:0 -19 0 ffff8d32e6d06180 1883348155 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883348174 E Ci:3:005:0 -19 0 ffff8d32e6d06180 1883348176 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883348180 E Ci:3:005:0 -19 0 ffff8d32e6d06180 1883348181 S Ci:3:005:0 s 80 06 0100 0000 0008 8 < ffff8d32e6d06180 1883348185 E Ci:3:005:0 -19 0

The -19 error codes mean the device is considered to be disconnected, probably as a result of the connect- and link-state changes. At this point the kernel gives up; it had tried to recover the original device and the recovery failed.

In the third trace (where the device continued to work after the resume), there was no connect-state or link-state change reported. The reset was okay and everything proceeded normally.

I don't know that there's much we can do about this sort of thing -- that is, transient disconnects during reset-resume recovery. This was something that clearly happened _after_ the card reader had been resumed; it can't be chalked up to power loss during the suspend. To the kernel, it looked like the card reader really had been disconnected from the USB bus during the reset and a new device connected in its place.

The xhci-hcd debugging information can't help; all it might say is that there was a disconnect and a connect, which we already know. To find out the cause it would be necessary to know what's going on inside the card reader's firmware.

You can check this interpretation of events by turning on usbcore dynamic debugging and seeing what the kernel log says when this happens again.

You may reply to this email to add a comment.

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

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

--- Comment #13 from Paul Ausbeck ([email protected]) --- Created attachment 308572
--> https://bugzilla.kernel.org/attachment.cgi?id=308572&action=edit
dmesg log, S/R, usb_storage device disconnect. dyndbg xhci_hcd, usbcore.

I've posted a dmesg log where the usb_storage device disconnects during resume and where dynamic_debug for modules xhci_hcd and usbcore are enabled. In the dmesg log the usbcore messages are not annotated with "usbcore" but as device related messages "usb 3-4:". There are just few extra messages with usbcore dynamic_debug enabled. Initially I thought that my misunderstanding was more profound, but after looking at source I found a few dev_dbg messages from the usbcore source in the log, for instance "Waited 0ms for CONNECT".

You may reply to this email to add a comment.

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

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

--- Comment #14 from Alan Stern ([email protected]) --- Created attachment 308573
--> https://bugzilla.kernel.org/attachment.cgi?id=308573&action=edit
Retry reset if there was a connection change

Please test the attached patch. It causes the kernel to retry if there was a connection change during a reset of a SuperSpeed device. I don't know if your card reader will just disconnect and reconnect again during the retry, and there may have been a very good reason for the original code to limit these retries to non-SuperSpeed devices. Still, let's see what it does.

You may reply to this email to add a comment.

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

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

--- Comment #15 from Paul Ausbeck ([email protected]) --- Created attachment 308575
--> https://bugzilla.kernel.org/attachment.cgi?id=308575&action=edit
S/R dmesg log, reset retry patch applied, usb_storage device still dis/reconnecting

The attached dmesg log has xhci_hcd and usbcore debug logging enabled. The retry patch code was not triggered as the "Connection change during reset, retrying\n" message does not appear in the log.

You may reply to this email to add a comment.

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

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

--- Comment #16 from Alan Stern ([email protected]) ---
I can't tell what's happening just from reading the dmesg log; I need to see a usbmon trace too. Maybe an xhci-hcd maintainer would be able to interpret the log better, but I can't.

However, the repeated 0x341 and 0x2a0 port-status values are new. They indicate that the card reader is behaving in some strange way, different from what it was doing before.

You may reply to this email to add a comment.

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

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

--- Comment #17 from Paul Ausbeck ([email protected]) --- Created attachment 308605
--> https://bugzilla.kernel.org/attachment.cgi?id=308605&action=edit
usbmon trace of emb-qm77 suspend/resume with connected xhci usb_storage device

You may reply to this email to add a comment.

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

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

--- Comment #18 from Paul Ausbeck ([email protected]) --- Created attachment 308606
--> https://bugzilla.kernel.org/attachment.cgi?id=308606&action=edit
emb-qm77 suspend/resume dmesg log with xhci_hcd & usbcore dynamic debug

You may reply to this email to add a comment.

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

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

--- Comment #19 from Paul Ausbeck ([email protected]) --- I have a couple of AAEON emb-qm77 Intel ivy bridge motherboards, ivy bridge being the first Intel chipset generation to natively support USB 3.0. Both of these machines exhibit the same or a similarly situated problem as previously reported for my Samsung ativ9, Intel broadwell, laptop, that is USB connected storage devices do not usefully survive suspend/resume cycles. Because emb-qm77 connected USB 3.0 storage devices, usb_storage and/or uas, reliably disconnect/reconnect on every suspend/resume, I feel like the emb-qm77 MB is a better representative of the class of machines exhibiting this problem than the Samsung ativ9 where the problem only sporadically occurs.

For me personally, machines of the ivy bridge to broadwell era are still eminently useful and would be even more useful if I could patch around this USB 3.0 storage device issue. Though the fault of these now longstanding problems could more accurately be ascribed to MB BIOS and/or device firmware failings, I feel like it may be easier and more general to patch around these problems at the OS kernel level rather than through individual BIOS or firmware patches. In particular, it seems conceptually desirable to extend the linux kernel's usb_persist mechanism to encompass disconnection and reconnection of USB 3.0 devices.

Before I pursue this idea further I would like to ask: Does anyone else think that this would be a useful or even possible concept?

If anyone is interested, I have previously attached usbmon, xhci_hcd, and usbcore traces of a emb-qm77 suspend resume cycle that encompass a connected USB 3.0 storage device.

You may reply to this email to add a comment.

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

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

--- Comment #20 from Alan Stern ([email protected]) --- When devices "reliably disconnect/reconnect" on the emb-qm77 system, do they work reliably afterward? Always, sometimes, or never?

Remember, the traces you have collected so far on the Samsung machine show the card reader device disconnecting/reconnecting on every suspend -- but on some of them it worked afterward and on some it did not.

I agree that it would be good to solve this problem somehow in the kernel. However, at this point we do not know enough about what is going wrong to tell if this is even possible, let alone how to do it. For all we know, the problem might be fixed by something as simple as adding a 10-ms delay during the resume procedure.

Also, I don't fully understand what you mean by "extend the linux kernel's usb_persist mechanism to encompass disconnection and reconnection of USB 3.0 devices". That's what it does right now -- in the case where the card reader worked following suspend/resume, it was because the device disconnected and reconnected and the usb-persist mechanism was successful. (In the cases where the card reader didn't work following suspend/resume, it was because the device disconnected and reconnected and then so many other errors occurred that the usb-persist mechanism was unable to cope and thus failed.)

You may reply to this email to add a comment.

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

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

Michał Pecio ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------
CC| |[email protected]

--- Comment #21 from Michał Pecio ([email protected]) ---
We have those PORTSC messages telling what the xHCI controller thinks about the state of particular root hub ports and what gets sometimes written to change this state. See xHCI spec 5.4.8 for the meaning of those bits. Note that the kernel doesn't write back exactly the same things it reads, because some bits (notably PED) are "write 1 to clear" or other oddities, see section 5.1.1 for the meaning of bit attributes.

In this latest case, I suppose you mean device on port 3-2.

Suspending:

[ 1097.437841] xhci_hcd 0000:00:14.0: Set port 3-2 link state, portsc: 0x1203,

write 0x11261

1203 seems to be the normal working state for a SuperSpeed device:
12 - SuperSpeed, port power on, top bit of link state is 0 0 - link state U0, not currently resetting
3 - no overcurrent, port is enabled and connected

11261 requests transition to U3 (port suspend).

But after resuming things get a little different:

[ 1097.766164] xhci_hcd 0000:00:14.0: Port change event, 3-2, id 6, portsc:

0x100080

That's a lot of zeros here. Link disabled, port disabled, not connected, not powered, no overcurrent but overcurrent status has changed since the last time the change bit was cleared or observed clear.

So I can't be sure what happens here, I'm far from expert on USB 3.0 link management and xHCI root hubs, but it looks like hardware took action to completely disable this port in the meantime, possibly due to actual overcurrent or some HW bug or other problem.

Then we see:

[ 1098.777817] xhci_hcd 0000:00:14.0: set port power 3-2 ON, portsc: 0x100080
[ 1098.881792] xhci_hcd 0000:00:14.0: Get port status 3-2 read: 0x1002a0,
return 0x802a0
[ 1099.080653] xhci_hcd 0000:00:14.0: Port change event, 3-2, id 6, portsc:

0x21203

The value written by the kernel isn't logged, but a moment later we see 'powered up' and the link advancing to RxDetect state and then it's up and running.

Then it looks like USB core registers disconnection, resets the port and the device works normally from there.

You may reply to this email to add a comment.

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

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

--- Comment #22 from Michał Pecio ([email protected]) --- Note that these numbers are completely different from the other cases, so I'm not sure if the cases are really related.

For example, the very first log posted here shows suspending the devices from U1 low power state to U3 and then the device is at U0 after resuming with "connect status changed". Perhaps it got power cycled by HW?

The kernel immediately attempts some control transfers which fail, maybe device firmware is waiting for a reset?

The device gets reset after the control transfers fail:

[  158.205065] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x1203, return
0x203
[  158.205101] xhci_hcd 0000:00:14.0: set port reset, actual port 3-4 status  =
0x1311
[  158.268775] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x4202d0,

return 0x4102d0

Things are different from the other case, because "connect status change" and "port link state" change are set. And the 'd' stands for 'port reset' (still pending) and link state SS.Inactive.

Then it comes back:

[  158.332893] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x621203,

return 0x510203

If not a HW bug then I would guess the device disabled/enabled its upstream port. And xhci_hcd has flagged it as "inactive" and will be returning -ENODEV on URB submissions:

[  158.389217] usb 3-4: reset SuperSpeed USB device number 2 using xhci_hcd
[  158.404819] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[  158.404838] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[  158.404847] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[  158.476865] xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping usb3 port
polling
[  158.508898] usb 3-4: reset SuperSpeed USB device number 2 using xhci_hcd
[  158.524913] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[  158.524933] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[  158.524941] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link

inactive

I see no way to clear this VDEV_PORT_ERROR flag, I guess the core needs to destroy and recreate the device?

Then the port seems to be put into U3.

[  158.629069] xhci_hcd 0000:00:14.0: Set port 3-4 link state, portsc: 0x1203,

write 0x11261

[  158.656170] usb 3-4: USB disconnect, device number 2

And later the device comes up after being reset once again.

You may reply to this email to add a comment.

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

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

Mathias Nyman ([email protected]) changed:

What |Removed |Added
----------------------------------------------------------------------------

                 CC|                            |[email protected]
                   |                            |om

--- Comment #23 from Mathias Nyman ([email protected]) --- Looks like main issue is that the device is disconnected during suspend/resume.

USB3 devices will try to train the link automatically after connect, and get it up to a full enabled and running U0 state without driver interaction.

I see at least 3 different outcomes after device was re-connected during suspend/resume

1. Device link training was attempted early in resume (or during suspend), but before xHC host was really capable to di its part.xHC sets a CAS flag (cold attach state) to tell xhci driver device needs to reset to get the link in shape. CAS is xhci specific, not part of usb specification, so xhci driver reports a "compliance mode" state to usb core instead. This is the idd 341 state Alan talked about. For som unknown reason I can't see the expected "Connect status change" here.

2. link is successfully retrained during resume, link reaches U0/enabled state. We also see the "Connect Status Change" (CSC) set. This link state looks exactly like a successful resume from U3, except for the CSC flag. It's possible usb core assumes device is now successfully resumed into U0 configured state even if it is in U0 Default state, and needs to be addressed and configured before it can respond to most requests.

3. reset-resume races with link error (ss.Inactive state). If link goes to ss.Inactive it can only be recovered by a (device) reset. In this race case the link goes to ss.inactive at the same time a usb core resets the device.
- link goes to ss.inactive (xhci driver and usb core are not yet aware of this)
- usb core reset device as part of reset-resume path.
- xhci driver sees ss.Inactive error state before reset, sets a flag that prevents transfers. logs show "Can't queue urb, port error, link inactive" messages.
- device is reset and recovers, flags stays forever preventing transfers. This needs to be fixes in xhci driver

You may reply to this email to add a comment.

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

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

--- Comment #24 from Alan Stern ([email protected]) --- Mathias, your analysis looks right to me.

I suspect the whole problem comes down to two things: (1) The card reader gets disconnected during suspend, perhaps because of lack of power. (2) Re-establishing the USB-3 link races with the reset-resume processing in usbcore. That's why I suggested adding a 10-ms delay (maybe it needs to be longer) at the right spot might fix everything; it would give the link time to come back up before all the resets and other stuff start happening.

On the other hand, it might also be possible to resolve the races by changes to xhci-hcd. After all, re-establishing a link is already part of what our reset routines do. That would be preferable, if it works out.

You may reply to this email to add a comment.

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

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

--- Comment #25 from Paul Ausbeck ([email protected]) --- Alan, I think there is some confusion over my terminology. When I say that something reliably disconnects, that means the disconnect happens on every suspend resume. The emb-qm77 disconnect happens on every suspend/resume, whereas on the Samsung machine the disconnect only happens say 20% of the time.

When I say that a disconnect happens, it is invariably followed by a reconnection. This means that in every case the device continues to work just fine. The problem is that the usb_storage, or uas, context is lost and the device must be remounted.

When I suggest to extend the kernel's usb_persist mechanism, I make a purely philosophical point. In all cases at issue here, the device is not actually being disconnected/reconnected, the D/R is being simulated via software. I feel like such a software simulated disconnect/reconnect falls into the same philosophical area as the current usb_persist mechanism. If the disconnect/reconnect is happening in order to "cure" the device, then somehow the connection state should be preserved so that higher level actors, such as usb_storage and uas don't know about the disconnect/reconnect. Currently, when a disconnect/reconnect happens, the reconnected device gets a new "device number", and since this "device number" is visible up the chain, the chain inherently fails and must be re-established all the up to filesystem mount..

You may reply to this email to add a comment.

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

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

--- Comment #26 from Paul Ausbeck ([email protected]) --- Perhaps I should further explain another point. On the Samsung machine, when the disconnect/reconnect does not happen, which is most of the time, the device continues to function properly. Further, since the device number does not change, upstream actors continue to function without knowledge of resets and what not occurring down lower in the stack, so the associated filesystem does not have to be remounted and any userland applications with open file handles for the device do not have to be restarted. This situation where the disconnect/reconnect does not happen could be viewed as a success of the current usb_persist mechanism. What would be nice would be to extend the usb_persist mechanism so that the connection could be persisted across pseudo disconnect/reconnect.

I think it would be a good idea to find out if a delay of some sort would have some utility against the problem on either or both of these machines. If someone would post and/or email me a code snippet that accomplishes such a delay and suggest where to place such a snippet, I have source build trees on both of these machines and could relatively easily test. A patch would also do but since the delay may need to be moved around to find the right location, we may as well start with the most portable delay code possible. I don't have much experience with linux kernel code but I do have significant software experience, including Microsoft Windows driver experience.

I also think it may be useful to say again that the emb-qm77 machine may be the better machine serve canonically and therefore to focus on initially. I say this because the problem there is repeatable, the problem trace has the same form on every suspend/resume. The Samsung machine has an asynchronous character, the disconnect/reconnect may or may not happen, when it does happen the exact point in the trace where it happens may differ from one occurrence to another.

You may reply to this email to add a comment.

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

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

--- Comment #27 from Paul Ausbeck ([email protected]) --- Also, if the delay snippet that I wrote of previously were to include a provision for changing the delay via the sysctl mechanism, that would likely also be helpful. I could of course research this on my own, but if a domain expert would provide assistance it would save me some time.

You may reply to this email to add a comment.

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

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

--- Comment #28 from Paul Ausbeck ([email protected]) --- Michael, Mathias: I concur that the emb-qm77 machine has some sort of hardware/BIOS bug. It does not matter what type of device is plugged into a USB 3.0 port, that device will always disconnect/reconnect during resume from suspend and there will always be some kernel log entry related to overcurrent. My feeling is that there is no actual overcurrent and that the overcurrent detection mechanism is faulty. To me, the overcurrent detection is a red-herring, it would be nice to keep the device stack together even if there is a hardware bug. I think one salient point is that I personally own two entirely different machines that both would benefit from the linux USB stack keeping the device number the same across a suspend/resume related disconnect/reconnect. If I have two such machines, statistically it is likely that there are quite a few such machines out there. In fact, there may already be another such machine in my collection, I just don't know it yet.

I will also say that it may be nicer/easier to keep the disconnect/reconnect from happening, but my feeling just now is that that approach would likely be more machine specific. What I'm trying to say is that allowing disconnect/reconnect to happen and keeping port context to allow the device number to remain unchanged may be a more general solution. It would be nice to formulate a solution that would work across all members of the class of disconnect/reconnects that occur for some reason other than physical unplug/replug.

You may reply to this email to add a comment.

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

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

--- Comment #29 from Paul Ausbeck ([email protected]) --- I think it somewhat important to say why I reported the Samsung problem initially when I think that the emb-qm77 board may be a better canonical example. The emb-qm77 board appears canonical to me only in that the problem is reliably repeatable. The Samsung laptop is actually canonical in the relative worth of a kernel fix. The emb-qm77 machine has 5 SATA ports, so I would not dream of actually using its USB 3.0 ports for mounting storage devices that need to survive suspend/resume.

On the other hand, the Samsung laptop has only one m.2 SATA slot and one SD card slot. Right now, the ativ9 contains its original Samsung 256GB m.2 SATA drive and a Samsung 512GB U1/A2 SD card. I use the SD card for larger/downloaded files: video, images, audio, pdfs, downloaded web pages, compressed tarballs, and the m.2 SATA drive for everything else. The ativ9 SD card reader limits the SD card to ~20MB/s, rather less than its 100MB/s U1 rating. Even at 20MB/s the USB 3.0 connection can theoretically support 40K 512B transactions per second. This is more than the few thousand specified for the SD card's A2 rating. Knowing USB, though, the number of transactions actually available may likely be substantially less than 40k/s. Still, in my experience, USB 3.0 can support a few thousand transactions/s.

I really like these Samsung U1/A2 cards. Even in a compromised reader like in the ativ9, it is very possible to build a linux kernel on the SD card. The linux kernel build is so CPU limited that it barely notices that it's on an SD card. These U1/A2 cards generally behave quite similarly to mmc connected soldered flash as in typical phone. I also trust these cards degrade properly in that write problems start surfacing while it is still possible to recover previously written data from the card. I don't want to imply that write problems surface that often because they don't. Again, I really like these Samsung U1/A2 cards.

I really like the Samsung ativ9 laptop as well. I paid $500 for it ten years ago. It is small, light and physically robust. It has a lot of bright display pixels. It is efficient and thus far the battery works as if new. It has an Atheros QCA6174 radio which actually does 2x2 MIMO. The wifi throughput can be 25MB/s on a 40MHz 2.4GHz connection, and 50MB/s on a 80MHz 5GHz connection. The QCA6174 firmware crashes on most suspend/resume cycles but the system recovers without any user intervention. I would not trade the known limitations of the ativ9 for any newer system with unknown limitations.

You may reply to this email to add a comment.

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

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

--- Comment #30 from Paul Ausbeck ([email protected]) --- Created attachment 308612
--> https://bugzilla.kernel.org/attachment.cgi?id=308612&action=edit
usbmon trace, emb-qm77, S/R, actually physical disconnect while suspended

This usbmon trace is from emb-qm77 with the USB storage device being physically removed while the system was suspended. There is quite a lot of communication with the associated USB hub but of course no device communication during resume. Note that there is no device communication during suspend either. This is somewhat unexpected to me but perhaps it shouldn't be.

You may reply to this email to add a comment.

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

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

--- Comment #31 from Paul Ausbeck ([email protected]) --- Created attachment 308613
--> https://bugzilla.kernel.org/attachment.cgi?id=308613&action=edit
xhci_hcd and usbcore dmesg trace, emb-qm77, S/R, USB storage manually disconnected

This is a dmesg log fragment with xhci_hcd and usbcore dynamic debug enabled, suspend/resume events, with the USB storage device being physically unplugged wile the machine is suspended. This attachment is matched with the previous attachment, a usbmon trace.

You may reply to this email to add a comment.

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

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

--- Comment #32 from Paul Ausbeck ([email protected]) --- I thought it might be useful to gather data on what an actual physical disconnect looks like during suspend/resume. I've run a test where I physically remove the USB storage device while the machine is suspended and then trigger resume. The trace data looks somewhat similar to the software simulated disconnect but without any device communication attempts and without any subsequent reconnect. The attached test data relates to the emb-qm77 MB.

You may reply to this email to add a comment.

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

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

--- Comment #33 from Alan Stern ([email protected]) --- Created attachment 308614
--> https://bugzilla.kernel.org/attachment.cgi?id=308614&action=edit
Add a configurable delay before reset-resumes

As far as I can tell, the card reader disconnects from the Samsung system _every_ time you go through a suspend/resume cycle. For example, in the usbmon trace you attached to comment #9, where the reader worked after the resume, there was a disconnect and reconnect. You may not be aware of them because they are hidden by the usb-persist mechanism.

And by the way, these disconnects are not "software simulated". They are real, honest-to-goodness disconnections. Yes, the disconnection is only electrical, not physical (the wires remain attached), but as far as the computer hardware is concerned there is no difference.

In any case, you can try the attached patch. It adds a delay before every reset-resume, and you can set the length of the delay (in milliseconds) by writing to the /sys/module/usbcore/parameters/reset_resume_delay file.

You may reply to this email to add a comment.

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

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

--- Comment #34 from Paul Ausbeck ([email protected]) ---
Alan: It may be that the usbmon trace associated with comment #9 is not what I thought it was. Since I can't readily interpret these traces I can't verify that they contain what I think they contain. I may have made a mistake.

When I say that a device disconnects/reconnects I get this information from the dmesg log. I did my best to match the usbmon trace to a proper dmesg log but I may have made a mistake. I want to emphasize that every time the device disconnects/reconnects as far as the dmesg log is concerned, the USB filesystem is unmounted. Every time that the device merely resets and does not disconnect/reconnect the USB filesystem remains mounted.

Here is a log snippet where the device, 3-4, disconnects/reconnects:

[22784.760311] usb 3-4: USB disconnect, device number 3
[22784.761239] pci_bus 0000:01: Allocating resources
[22784.761855] pci_bus 0000:01: Allocating resources
[22784.762047] done.
[22784.762056] random: crng reseeded on system resumption
[22784.876977] PM: suspend exit
[22784.878740] usb 2-4: new full-speed USB device number 15 using xhci_hcd
[22785.031677] usb 2-4: New USB device found, idVendor=0cf3, idProduct=e300,
bcdDevice= 0.01
[22785.031687] usb 2-4: New USB device strings: Mfr=0, Product=0,
SerialNumber=0
[22785.036360] usb 2-4: USB disconnect, device number 15
[22785.214926] usb 3-4: new SuperSpeed USB device number 4 using xhci_hcd

Here is what a reset with no disconnect/reconnect looks like:

[   58.003736] usb 3-4: reset SuperSpeed USB device number 2 using xhci_hcd

If the device is always disconnecting/reconnecting at the usbmon level, this is not always being propagated up to the usbcore level. To the extent that is true, the usb_persist mechanism is already working at least part of the time. If usb_persist is already working part of the time that should make it easier to get it to work all the time.

Just to verify that I did not make a mistake on comment #9, I'll attach another usbmon trace where there is no disconnect/reconnect at the usbcore level. The trace that I'm attaching has Bi/Bo:3:002 in every line. I interpret this as meaning that the host is only talking to the USB storage device. When a disconnect/reconnect occurs I also see usbmon lines that contain Bi/Bo:3:001, which I interpret as talking to the associated hub, and Bi/Bo:3:003 which I interpret as talking to the reincarnated device through a new device ID.

You may reply to this email to add a comment.

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

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

--- Comment #35 from Paul Ausbeck ([email protected]) --- Created attachment 308616
--> https://bugzilla.kernel.org/attachment.cgi?id=308616&action=edit
as promised usbmon trace with usbcore reset but no usbcore disconnect/reconnect

You may reply to this email to add a comment.

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

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

--- Comment #36 from Paul Ausbeck ([email protected]) --- Oops, my just posted usbmon trace does contain urbs that I would interpret as talking to the associated hub, for some reason I just missed them on initial read. This is good as I was expecting hub destined urbs. But the idea that the device ID does not change is still like I initially interpreted. In the just posted trace I only see two addresses: Bi/Bo:3:001 and Bi/Bo:3:002. In a trace with a disconnect/reconnect there would be three addresses, always Bi/Bo:3:001, but two device addresses, say Bi/Bo:3:002 initially and then Bi/Bo:3:003. Depending upon how many times the disconnect/reconnect has occurred since boot the device numbers may be larger but always sequential.

I've looked again at the trace from comment #9 and there are two device addresses. Curiously, device 4, presumably newer, appears before device 3, presumably older, then comes back again. I don't know what actually happened. Perhaps I traced the wrong host controller, but perhaps not. There is a second xhci host controller that I might have traced, and it does encompass two uvcvideo devices, but according to lsusb both of these devices have the same device ID and differ only in interface number. Since there is only one camera, the two interfaces must be an artifact of the physical device implementation. Anyway, I wouldn't put too much stock into the trace from comment #9. If you can make sense of it in light of what I've just told you, please do so.

Oh, after reviewing my comment #10 I remember that on that run I mistakenly had a USB uas device plugged into the same host controller as the SD card reader. From the amount of trace information for each, I would guess that device 003 is the uas SSD and device 004 is the SD card reader.

You may reply to this email to add a comment.

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

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

--- Comment #37 from Alan Stern ([email protected]) --- The usbmon trace in comment #35 does contain a disconnect/reconnect. And it did propagate up to the usbcore level, which is where the usb-persist mechanism lives. usb-persist is what keeps it from going any farther, in particular, from showing up in the dmesg log.

In case you're curious, in that trace:

ffff9bb60d581f00 127168165 S Ci:3:001:0 s a3 00 0000 0004 0004 4 < ffff9bb60d581f00 127168171 C Ci:3:001:0 0 4 = 03020100 ffff9bb60d581f00 127168174 S Co:3:001:0 s 23 01 0010 0004 0000 0 ffff9bb60d581f00 127168181 C Co:3:001:0 0 0

The first two lines are Get-Port-Status for port 4 (the port the card reader is plugged into) near the start of the resume, with the returned status showing a connect-change. The next two lines are a command to clear the port's connect-change status bit. The fact that these lines are present is proof that usbcore was aware of the disconnection, because usbcore is the component that ordered the status bit to be cleared.

You may reply to this email to add a comment.

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

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

--- Comment #38 from Michał Pecio ([email protected]) --- (In reply to Paul Ausbeck from comment #31)

This nicely illustrates why usb_persist is hard (and dangerous: you could disconnect the device and connect a different one). This log is *exactly* the same as the one you posted before, except that when the kernel restores power, the root hub port goes to RxDetect state (detecting electrical SuperSpeed connection) and stays there because the device is gone.

[  368.488920] xhci_hcd 0000:00:14.0: Set port 4-2 link state, portsc: 0x1203,
write 0x11261
[  368.859068] xhci_hcd 0000:00:14.0: Port change event, 4-2, id 6, portsc:
0x100080
[  369.862706] xhci_hcd 0000:00:14.0: set port power 4-2 ON, portsc: 0x100080
[  369.966674] xhci_hcd 0000:00:14.0: Get port status 4-2 read: 0x1002a0,

return 0x802a0

I suspect that usb_persist fails in this case because it simply doesn't consider overcurrent ports to be eligible, or something like that.

You may reply to this email to add a comment.

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

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

--- Comment #39 from Paul Ausbeck ([email protected]) --- OK, from Alan's comment it appears that the ativ9 disconnect is somehow too problematic for the usb_persist code to handle. However, if this is so, it's still not clear to me how allowing the disconnect propagate upward allows the device to reconnect with an incremented device ID. Maybe the delay will be instructive. I will test that tomorrow.

Michal says that usb_persist may not consider the emb-qm77 overcurrent error to be persist-eligible. That might be relatively easy to quirk around. Any suggestions about where that might go?

You may reply to this email to add a comment.

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

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

--- Comment #40 from Alan Stern ([email protected]) --- usb-persist doesn't care whether a port has an overcurrent condition. But it also doesn't check for overcurrents, and so it might not work if the condition is present. That's not a common thing, after all.

As for how allowing a disconnect to propagate upward allows a device to reconnect later on... There's nothing special about it. That's what happens every time a device is disconnected.

When usb-persist fails, there's nothing it can do. The only possible course of action is to allow the disconnect to be processed by the kernel's normal mechanisms. Once that's done, there's nothing to prevent another connection from occurring -- no need for anybody to "allow" anything.

You might just as well ask how unplugging as USB cable allows another device to be plugged in (or the same device to be plugged in again). And when the next device connects, it will naturally receive an incremented device ID.

You may reply to this email to add a comment.

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

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

--- Comment #41 from Paul Ausbeck ([email protected]) --- I've installed the reset delay to both machines. With the default delay of 500ms, the ativ9 connected SD card now survives suspend/resume in that the card remains mounted post resume, thus far >30 successive times. The reset delay has no effect on the emb-qm77 machine. My preliminary dmesg log study indicates that the connected storage device is not being reset, perhaps because the overcurrent error disqualifies it. I will investigate further when I return from bike riding.

Alan, thank you very much for the delay code. Even if a more general solution remains elusive, I can at least use my ativ9 laptop as I would like.

You may reply to this email to add a comment.

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

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

--- Comment #42 from Alan Stern ([email protected]) --- The emb-qm77 system sees to be a special case, with a real hardware problem. It reports overcurrent conditions on every port during resume -- even ports that aren't connected to a device.

usb-persist fails when an overcurrent condition is present. Not because the condition is disqualifying, but merely because usb-persist was never given the capability of handling it. In theory this capability could be added. But would it be worthwhile? How common are systems with this hardware bug?

You may reply to this email to add a comment.

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

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

--- Comment #43 from Mathias Nyman ([email protected]) --- Created attachment 308620
--> https://bugzilla.kernel.org/attachment.cgi?id=308620&action=edit
partial fix to sort xhci-hcd side issue that prevents urb queuing

Patch so ensure xhci driver does not unnecessary prevent transfers, and thus causing the recovery after resume to take even longer.

should sort out these extra messages in the log:

[73415.446721] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[73415.446746] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[73415.446755] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[73415.474680] xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping usb3 port
polling
[73415.550753] usb 3-4: reset SuperSpeed USB device number 8 using xhci_hcd
[73415.566718] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[73415.566738] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link
inactive
[73415.566746] xhci_hcd 0000:00:14.0: Can't queue urb, port error, link

inactive

reset-resume may still fail, and device get disconnected/reconnected

You may reply to this email to add a comment.

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

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

--- Comment #44 from Paul Ausbeck ([email protected]) --- Mathias, I tested your patch and with Alan's reset_resume_delay=0. Your patch eliminated all "...link inactive" messages in the log, however the initial problem whereby reset is not always successful returned. As of now, it looks like an inactive link causing reset failure or delay is not contributing to the problem that I initially reported.

You may reply to this email to add a comment.

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

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

--- Comment #45 from Paul Ausbeck ([email protected]) --- Things have taken an unexpected turn. I tested a reset_resume_delay=500 together with Mathias' urb queuing patch and my original problem, unmount of the internal SD card upon resume, returned. I was expecting that I would not have the unmount problem with this configuration. Right now, it looks like Mathias' patch somehow interferes with reset. I have again reconfigured without Mathias' patch and with reset-resume_delay=500 and have again confirmed that the unmount problem does not occur. I will look at this further and post some traces/logs.

You may reply to this email to add a comment.

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

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

--- Comment #46 from Mathias Nyman ([email protected]) --- Created attachment 308630
--> https://bugzilla.kernel.org/attachment.cgi?id=308630&action=edit
detect disconnected USB3 devies early in resume

This patch has a bit of different approach than adding delay to let link settle. Trys to detect the disconnected USB3 device as early as possible in resume, and reset devices as soon as possible. Idea is that maybe link is in "better" shape if we reset it immediately instead of first trying futile requests, let link fail , and then giving it more time to recover before reset.

Best case is that reset-resume is immediately used here (if persist is enabled), and device may prevent visible disconnect and unmount.

If this does not happen then it should at least fail faster and do visible disconnect a bit earlier

You may reply to this email to add a comment.

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

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

--- Comment #47 from Paul Ausbeck ([email protected]) --- After some more testing it now appears that Alan's reset_resume_delay patch is not a true solution to the ativ9 SD card reader unmount problem. After I applied and unapplied Mathias' patch the original problem returned. I've tried to get back to the "lucky" state where unmounts weren't happening on S/R but thus far I can't get there.

You may reply to this email to add a comment.

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

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

--- Comment #48 from Paul Ausbeck ([email protected]) --- I spent some time over the weekend instrumenting the kernel so that I could use kdb to poke around kernel memory. I particularly wanted to examine the contents of the variable reset_resume_delay which turned out to have the value of 0x1f4 as I was expecting. I first looked at /dev/mem as a method of reading kernel memory but found that that method has been essentially deprecated and not documented as so. I then instrumented for kdb/kgdb and eventually found that as far as sysrq is concerned, the ativ9 left alt key is different from its right alt key.

I then found that if kdb is active for long enough, kernel stalled, then once the kernel again runs, the SD card reader will disconnect and reconnect similarly to what happens sporadically on resume from suspend. I'm still not certain about this observation. It hasn't happened enough times to be certain of stall time requirements or even of correlation. I've just finished disabling various systemd daemon watchdog timers that were confusing the issue. If this kdb correlation turns out to be real, I think it should be a useful clue.

I've got a kdb breakpoint set on the usb_disconnect function. If I can figure out how to keep the system from switching virtual consoles when it hits the breakpoint, I will acquire a stack backtrace.

You may reply to this email to add a comment.

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

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

--- Comment #49 from Paul Ausbeck ([email protected]) --- I will try Mathias' latest patch once I gain more confidence about what I'm seeing. I don't want to again report success only later to recant.

You may reply to this email to add a comment.

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

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

--- Comment #50 from Michał Pecio ([email protected]) --- Hmm, are you sure you need the debugger and wouldn't it be enough to patch the code you are interested in to print whatever things you need?

You can use printk() which works like printf() for variables and dump_stack() to print a stack trace whenever you want, without pausing execution for more than a few microseconds and causing things to time out/disconnect/etc. You may need to include <linux/printk.h>.

You may reply to this email to add a comment.

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

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

--- Comment #51 from Paul Ausbeck ([email protected]) --- In a previous life, I found that debuggers, even kernel debuggers could be quite useful. SoftIce on Windows 95 and windbg on Windows NT were my special friends. I was demonstrably more productive than my peers and it's more than possible that their refusal to master kernel debugging contributed to that gap.

kdb is something like SoftIce and it appears that kgdb is something like windbg. I will first master kdb and only then kgdb. As of a couple of days use I still don't have that spider sense of kdb. Just now I lost the opportunity to get a stack backtrace because I did not interpret a kdb stop correctly.

You may reply to this email to add a comment.

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

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

--- Comment #52 from Paul Ausbeck ([email protected]) --- Created attachment 308645
--> https://bugzilla.kernel.org/attachment.cgi?id=308645&action=edit
kdb triggered disconnect usbmon trace

You may reply to this email to add a comment.

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

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

--- Comment #53 from Paul Ausbeck ([email protected]) --- Created attachment 308646
--> https://bugzilla.kernel.org/attachment.cgi?id=308646&action=edit
kdb triggered disconnect, dmesg tail

I have correlated disconnection of the USB connected SD card with stalling the kernel with kdb. Thus far, a long kdb stall, perhaps as long as overnight, is necessary for the SD card to disconnect upon resuming kernel operation. Interestingly, the disconnection is not immediate, minutes elapse between kernel resumption and device disconnection. Also interesting is that once the device starts disconnecting, it will disconnect several times, maybe indefinitely, with several minutes elapsed time between each hit of the usb_disconnect breakpoint. When the usb_disconnect breakpoint it hit, backtrace shows hub_event as the calling routine.

The attached file is a dmesg fragment starting upon kernel resumption via the kdb "go" command. The previous attachment is a usbmon trace of the same activity period.

You may reply to this email to add a comment.

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

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

--- Comment #54 from Mathias Nyman ([email protected]) --- I'm not sure if the kdb stall is helpful, or if it just adds one more moving part to this whole issue, possibly even causing usb link issues. The USB SD device, and xHCI controller are probably still running, expecting cpu/device drivers to handle certain things in time.

Anyways, your dmesg does reveal another issue in recovering links in ss.inactive error state. port_event() in hub.c ends up resetting just the port, even if a usb device is present and the whole device should be reset. After a successful reset port_event() calls hub_port_connect_change(..., portstatus, portchange) with old, stale, pre-reset portstatus value.

Details:
Link goes to ss.Inactive error state "0x2c0", this is common on disconnect before link goes to rx.detect. Driver gives it some time before reset:

[62691.183508] xhci_hcd 0000:00:14.0: Transfer error for slot 6 ep 3 on
endpoint
[62691.204674] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2c0, return
0x2c0
[62691.204720] usb usb3-port4: Wait for inactive link disconnect detect
[62691.228672] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2c0, return
0x2c0
[62691.228722] usb usb3-port4: Wait for inactive link disconnect detect
[62691.252648] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2c0, return
0x2c0
[62691.252692] usb usb3-port4: Wait for inactive link disconnect detect
[62691.276646] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2c0, return
0x2c0
[62691.276695] usb usb3-port4: Wait for inactive link disconnect detect
[62691.300652] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2c0, return
0x2c0
[62691.300697] usb usb3-port4: Wait for inactive link disconnect detect

Here we only reset the port when we should reset the whole device. Looks like this is because USB3 portstatus doesn't show "connected" when link is in ss.Inactive error, and the following check in hub.c port_event() is true:

else if (!udev || !(portstatus & USB_PORT_STAT_CONNECTION)

                                || udev->state == USB_STATE_NOTATTACHED) {

[62691.300704] usb usb3-port4: do warm reset, port only
[62691.316596] xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping usb3 port
polling
[62691.356676] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2d0, return
0x2d0
[62691.356722] usb usb3-port4: not warm reset yet, waiting 50ms
[62691.408710] xhci_hcd 0000:00:14.0: Port change event, 3-4, id 15, portsc:
0x2a1203
[62691.408729] xhci_hcd 0000:00:14.0: handle_port_status: starting usb3 port
polling.
[62691.412657] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x2a1203,
return 0x310203
[62691.412787] usb usb3-port4: Connection change during reset, retrying
[62691.412812] xhci_hcd 0000:00:14.0: clear port4 connect change, portsc:
0x281203
[62691.412832] hub 3-0:1.0: port_wait_reset: err = -11
[62691.412837] usb usb3-port4: not enabled, trying warm reset again...
[62691.616651] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x281203,
return 0x300203
[62691.616709] xhci_hcd 0000:00:14.0: clear port4 reset change, portsc: 0x81203
[62691.616732] xhci_hcd 0000:00:14.0: clear port4 warm(BH) reset change,
portsc: 0x1203
[62691.616752] xhci_hcd 0000:00:14.0: clear port4 link state change, portsc:
0x1203
[62691.616768] xhci_hcd 0000:00:14.0: Get port status 3-4 read: 0x1203, return

0x203

port is now properly reset and ready in enabled u0 "0x1203" state. hub driver does however call hub_port_connect_change() with stale portstatus value still showing link in ss.Inactive "0x2c0":

[62691.672631] usb usb3-port4: status 02c0, change 0041, 5.0 Gb/s
[62741.591943] xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping usb3 port
polling
[62741.593180] usb 3-4: USB disconnect, device number 3

You may reply to this email to add a comment.

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

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

--- Comment #55 from Mathias Nyman ([email protected]) ---
Paul: Not sure if you still have time or interest in this, but I'm wondering if my two patches, attachment 308620 and attachment 308630 did improve your case at all?

I think any improvement or partial fixes would be welcome upstream.

If you have time and could compare something like 50 suspend/resume cycles, with and without the patches and see if there are fewer disconnects, less severe errors, or even faster recovery, then I think those patches are worth upstreaming.

Grateful for any testing you can do
Thanks

You may reply to this email to add a comment.

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

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

--- Comment #56 from Paul Ausbeck ([email protected]) --- Created attachment 308729
--> https://bugzilla.kernel.org/attachment.cgi?id=308729&action=edit
usbcore log of disconnect following reset

Mathias: I apologize for not immediately getting back. I am still working on this problem, albeit slowly, mostly due to my getting older. Unfortunately neither of your patches fixed my particular ativ0 SD card disconnect issue, though the last did help to jump-start investigation.

I am slowly instrumenting the ativ9 kernel to help me to understand the code path to disconnect. In addition adding/changing logging information, I've made a few changes to the code to get past some bailout points. I now have a trace where the reset code detects that the device, not hub port, is not responding properly and initiates a disconnect.

I have attached a log of the entire sequence with everything else stripped out. I've stripped other things as the log is long enough as it is.

I've thought from the outset that it may be necessary to disconnect and reconnect the device in order to successfully patch around this problem. I've gotten to the point where I can begin to see how to start coding on a patch to accomplish that and I will continue on that path unless I get a better suggestion.

One thing I haven't looked at yet is the warm reset concept. As far as I can tell, the current code is performing a "hot" reset. I think maybe I should look at trying a "warm" reset instead. If this seems important to anyone, please weigh in.

You may reply to this email to add a comment.

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