On 01/08/2014 08:50 PM, Alan Stern wrote:
On Wed, 8 Jan 2014, tatxarata wrote:
Since reporting this bug I've invested some time to get myself familiar
with USB protocol and analyzed attached capture files. It seems like
device resetoccurs after device returns urb_status=-75 (-EOVERFLOW).
Yes. The EOVERFLOW error is what causes the driver to do a reset.
This can be seen in attachment
https://bugzilla.kernel.org/attachment.cgi?id=120901 in packet #1987.
Also I've noticed that host tries to read device by chunks of 240
sectors while device returns on each query no more than 120 sectors
(61440 bytes).
That's not true in the log file you just mentioned. See packet #1955.
Sorry... my bad... Described reason of my confusion in the previous
message on the mailing list.
From traffic it is clearly seen that EOVERFLOW occurs after the device
is already mounted and while software tries to browse it's content.
When I do something like 'dd if=/dev/sdb of=/dev/null' where sdb is CF
card or mount and copy with shell commands host<->device communication
scheme is the same (240 sectors requested, 120 returned), but this
doesn't lead to EOVERFLOW. In that cases read speed is at about 80Mb/s.
So I suppose that something wrong happens only while software like
thunar or midnight commander tries to browse the contents of card (maybe
parallel threads trying to access card simultaneously?).
That wouldn't matter. usb-storage serializes accesses to the device.
With that knowledge I've tried to tweak some device parameters in /sys
filesystem. When I put value 60 in /sys/block/sd?/queue/max_sectors_kb
then all operates correctly without any resets. However in this case
read speed of card drops down by factor of two at around 40Mb/s.
When I set max_sectors_kb to 64 then device does reset upon mount in
thunar, however, surprisingly, this doesn't lead to dropping of device
mount, like in case of default value of 120. In this case read speed is
at about 89.5Mb/s, as expected by card specs. So I've added udev rule
that corrects value of max_sectors_kb to 64 upon device connection. For
now I can live with this 10 seconds latency of device mounting if latter
it works properly. However I think that the reason of this issue must be
clarified and fixed.
It seems like a bug in the device.
However in Windows 8 all (I mean this particular combination of
notebook, card reader and CF card) works fine with stable speed of about
75Mb/s. CF card also works without any issues in Nikon D800 body.
Also I really can't understand the difference of
mount/cd/ls/cp/mv/rm/umount in shell and the same operations in GUI via
Thunar.
Also tried to set queue/scheduler to noop with no effect.
In case of USB2.0 host<->device traffic looks pretty the same way as in
case of USB3.0. Host also tries to read device by chunks of 240 sectors
and device returns only 120. However for some reason this doesn't lead
to EOVERFLOW.
Main difference I've managed to find between usb 2.0 and 3.0 traffic is
the device initialization. In case of 3.0 there are some
CLEAR_FEATURE/SET_FEATURE requests that are missing in case of 2.0, so
maybe device operates differently by that reason.
Maybe, but I doubt it. Those requests are mostly concerned with Link
Power Management.
What happens if you connect the card reader to a USB-3 port using a
USB-2 cable?
With USB-2 cable all works fine except the speed.
Alan Stern
Things are getting more interesting.
I've tried to format card with ext4 and restored default value 120 of
max_sectors_kb . In that case mounting and writing to card with thunar
works fine at a solid speed of 90Mb/s, but reading is at about awful
1Mb/s. Capture shows a frequent stalls when after reading a chunk of
data device after 7 seconds of silence reports status -EPIPE (-32). No
EOVERFLOW errors occurred.
Same thing when I formatted it with mkfs.vfat, but write speed is at
about 50Mb/s.
At last I've formatted the card with photo camera and situation returned
to initial state.
Also I've ran into one more issue: after some extensive testing of this
device all of my USB3.0 ports stop working at all until reboot. dmesg on
kernel-3.10.17 on which I've done today's tests says something like:
[131396.290944] hub 3-0:1.0: hub_resume
[131396.290953] hub 3-0:1.0: port 4: status 0507 change 0000
[131396.290956] hub 3-0:1.0: state 7 ports 4 chg 0000 evt 0000
[131396.290959] hub 3-0:1.0: hub_suspend
[131396.290961] usb usb3: bus auto-suspend, wakeup 1
[131396.290962] usb usb3: bus suspend fail, err -16
...
[131396.290987] usb usb3: bus suspend fail, err -16
[131396.290989] hub 3-0:1.0: hub_resume
[131396.291003] hub 3-0:1.0: port 4: status 0503 change 0004
[131396.291010] hub 3-0:1.0: state 7 ports 4 chg 0010 evt 0000
[131396.301990] usb 3-4: usb wakeup-resume
[131396.302000] usb 3-4: finish resume
[131396.302062] hub 3-4:1.0: hub_resume
[131396.302104] hub 3-4:1.0: port 1: status 0503 change 0004
[131396.302187] hub 3-0:1.0: resume on port 4, status 0
[131396.302188] hub 3-0:1.0: port 4, status 0503, change 0004, 480 Mb/s
[131396.302191] hub 3-4:1.0: state 7 ports 3 chg 0002 evt 0000
[131396.312990] usb 3-4.1: usb wakeup-resume
[131396.313051] usb 3-4.1: finish resume
[131396.313126] hub 3-4.1:1.0: hub_resume
[131396.313166] hub 3-4.1:1.0: port 1: status 0101 change 0001
[131396.313284] hub 3-4.1:1.0: port 3: status 0507 change 0000
[131396.413864] hub 3-4:1.0: resume on port 1, status 0
[131396.413869] hub 3-4:1.0: port 1, status 0503, change 0004, 480 Mb/s
[131396.413875] hub 4-4.1.3:1.0: state 7 ports 3 chg 0000 evt 0008
[131396.413879] hub 3-4.1:1.0: state 7 ports 3 chg 0002 evt 0000
[131396.413925] hub 3-4.1:1.0: port 1, status 0101, change 0000, 12 Mb/s
[131399.033489] xhci_hcd 0000:00:14.0: Timeout while waiting for reset
device command
[131401.407420] xhci_hcd 0000:00:14.0: Timeout while waiting for a slot
[131401.407428] hub 3-4.1:1.0: couldn't allocate port 1 usb_device
[131401.407512] hub 4-4.1.3:1.0: state 7 ports 3 chg 0000 evt 0008
[131401.407525] hub 3-4.1:1.0: hub_suspend
[131404.027036] xhci_hcd 0000:00:14.0: Timeout while waiting for address
device command
[131406.407935] xhci_hcd 0000:00:14.0: xHCI host not responding to stop
endpoint command.
[131406.407940] xhci_hcd 0000:00:14.0: Assuming host is dying, halting host.
[131406.407971] xhci_hcd 0000:00:14.0: HC died; cleaning up
[131406.407993] hub 3-0:1.0: state 0 ports 4 chg 0000 evt 0000
[131406.407996] usb 3-4: USB disconnect, device number 2
[131406.407998] usb 3-4.1: USB disconnect, device number 24
[131406.408000] usb 3-4.1.3: USB disconnect, device number 25
[131406.408001] usb 3-4.1.3: unregistering device
[131406.408003] usb 3-4.1.3: unregistering interface 3-4.1.3:1.0
[131406.408080] usb 3-4.1.3: usb_disable_device nuking all URBs
[131406.408155] xhci_hcd 0000:00:14.0: Slot 26 endpoint 2 not removed
from BW list!
[131406.408162] usb 3-4.1: unregistering device
[131406.408163] usb 3-4.1: unregistering interface 3-4.1:1.0
[131406.408194] usb 3-4.1: usb_disable_device nuking all URBs
[131406.408240] xhci_hcd 0000:00:14.0: Slot 25 endpoint 2 not removed
from BW list!
[131406.408245] usb 3-4: unregistering device
[131406.408246] usb 3-4: unregistering interface 3-4:1.0
[131406.408284] usb 3-4: usb_disable_device nuking all URBs
[131406.408341] xhci_hcd 0000:00:14.0: Slot 1 endpoint 2 not removed
from BW list!
[131406.408355] hub 4-0:1.0: state 0 ports 4 chg 0000 evt 0000
[131406.408358] usb 4-4: USB disconnect, device number 2
[131406.408359] usb 4-4.1: USB disconnect, device number 55
[131406.408361] usb 4-4.1.3: USB disconnect, device number 57
[131406.408362] usb 4-4.1.3.3: USB disconnect, device number 0
[131409.221305] xhci_hcd 0000:00:14.0: Timeout while waiting for address
device command
[131409.221311] xhci_hcd 0000:00:14.0: Abort the command ring, but the
xHCI is dead.
[131409.422061] usb 4-4.1.3.3: device not accepting address 58, error -108
[131409.422073] hub 4-4.1.3:1.0: logical disconnect on port 3
[131409.422091] usb 4-4.1.3.3: unregistering device
[131409.422096] usb 4-4.1.3.3: unregistering interface 4-4.1.3.3:1.0
[131409.422131] sd 48:0:0:0: Device offlined - not ready after error
recovery
[131409.423379] usb 4-4.1.3.3: usb_disable_device nuking all URBs
[131409.423579] usb 4-4.1.3: unregistering device
[131409.423583] usb 4-4.1.3: unregistering interface 4-4.1.3:1.0
[131409.423623] usb 4-4.1.3: Failed to set U1 timeout to 0x0,error code -19
[131409.423628] usb 4-4.1.3: Set SEL for device-initiated U1 failed.
[131409.423630] usb 4-4.1.3: Set SEL for device-initiated U2 failed.
[131409.423699] usb 4-4.1.3: Failed to set U1 timeout to 0x0,error code -19
[131409.423703] usb 4-4.1.3: Set SEL for device-initiated U1 failed.
[131409.423706] usb 4-4.1.3: Set SEL for device-initiated U2 failed.
[131409.423709] usb 4-4.1.3: usb_disable_device nuking all URBs
[131409.424072] usb 4-4.1: unregistering device
[131409.424076] usb 4-4.1: unregistering interface 4-4.1:1.0
[131409.424128] usb 4-4.1: Failed to set U1 timeout to 0x0,error code -19
[131409.424132] usb 4-4.1: Set SEL for device-initiated U1 failed.
[131409.424135] usb 4-4.1: Set SEL for device-initiated U2 failed.
[131409.424186] usb 4-4.1: Failed to set U1 timeout to 0x0,error code -19
[131409.424188] usb 4-4.1: Set SEL for device-initiated U1 failed.
[131409.424189] usb 4-4.1: Set SEL for device-initiated U2 failed.
[131409.424191] usb 4-4.1: usb_disable_device nuking all URBs
[131409.424284] usb 4-4: unregistering device
[131409.424288] usb 4-4: unregistering interface 4-4:1.0
[131409.424308] usb 4-4: Failed to set U1 timeout to 0x0,error code -19
[131409.424310] usb 4-4: Set SEL for device-initiated U1 failed.
[131409.424311] usb 4-4: Set SEL for device-initiated U2 failed.
[131409.424346] usb 4-4: Failed to set U1 timeout to 0x0,error code -19
[131409.424348] usb 4-4: Set SEL for device-initiated U1 failed.
[131409.424349] usb 4-4: Set SEL for device-initiated U2 failed.
[131409.424350] usb 4-4: usb_disable_device nuking all URBs
--
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
