Re: USB disk speed regression WD Elements - with bisect result 22547c4cc4fe20698a6a85a55b8788859134b8e4

[Zdenek Kabelac]

Dne 25.7.2017 v 16:25 Alan Stern napsal(a):
> On Tue, 25 Jul 2017, Zdenek Kabelac wrote:
>
> > Dne 24.7.2017 v 16:41 Alan Stern napsal(a):
> > > On Mon, 24 Jul 2017, Zdenek Kabelac wrote:
> > >
> > > > Hi
> > > >
> > > > I've problem with my USB storage devices:  WD Elements 1TB.
> > > > (Bus 004 Device 002: ID 1058:10a8 Western Digital Technologies, Inc. Elements
> > > > Portable (WDBUZG))
> > > >
> > > >
> > > > After kernel >4.9  when disk is attached via cable it has very low speed
> > > > (less then 1MB/s).
> > > >
> > > > It can run at full speed (>22MB/s) when the Linux kernel is fully rebooted (so
> > > > disk is attached during the reboot of Lenovo T61, C2D, Fedora Rawhide).
> > > >
> > > > However when >4.9 kernel is running and disk is just attached it's very slow.
> > > >
> > > > I've played a bisect game - and the clean result has been:
> > > >
> > > > 22547c4cc4fe20698a6a85a55b8788859134b8e4
> > > >
> > > > When I just revert this patch with 4.13-rc1 - it's again running with full
> > > > speed even when disk is attached (thus no reboot is needed for full speed).
> > > >
> > > >
> > > > So while I've no idea what 22547c4cc4fe20698... is doing, it seems to have
> > > > some unpleasant side-effect on regular USB devices.
> > > >
> > > > So what else is needed to get this properly working ?
> > > > (assuming plain revert of  22547c4cc4fe20698 is unwanted).
> > > >
> > > > What more info can I provide to get this storage 'normally' usable without
> > > > rebooting the machine.
> > >
> > > Please post the dmesg logs showing what happens when the disk is
> > > first attached and operates slowly, and what happens when the disk is
> > > attached following a reboot and operates normally.
> >
> > So I'm attaching kernel traces from  kernel 4.8  & 4.12 from T61.
> >
> > Both are from full boot (all kernel: messages)
> >
> > In both cases - boot was with USB WD disk attached -
> > then I've detached USB disk and reattached again.
> >
> > On 4.8 this had normal speed all the time
> > On 4.12 after reattach -> slow speed.
> >
> > I should also add that on Lenovo T440s - there seems to be NO slowdown
> > when this WD Element drive is attached it works normally all the time.
> >
> > So it could be probably related to USB chipset on T61 ??
> >
> > For completeness I'm also attaching boot kernel trace from T440s where USB
> > disk is just attached and works with normal speed.
>
> The log shows that the drive is reconnecting at full speed (12 Mb/s)
> instead of high speed (480 Mb/s), which is why the communication
> becomes so slow.
>
> I think there's some weird timing issue going on.  Hard to tell from
> just the log, though.
>
> Please collect a usbmon trace, starting from just before the unplug and
> ending after the drive has reconnected at the slower speed.
> Instructions are in Documentation/usb/usbmon.txt.  Use bus number 0 for
> the trace, so we can see what's going on with both the high-speed and
> full-speed connections.  And collect traces for both 4.8 and 4.12.
>
> And try to avoid using any other USB devices during the test, to
> minimize the amount of excess information recorded in the trace.


Ahh nice spot - I've not been checking that message in detail - so maybe I 
should actually run another bisect - where:

"new high-speed USB device number..."

turned into:

"new full-speed USB device number 2 using uhci_hcd"
"not running at top speed; connect to a high speed hub"

As I've just ended with a commit that made 'slow-speed' reality
but I need to find the commit having impact on connecting message

Zdenek