Date: Tue, 25 Jul 2017 10:25:34 -0400 (EDT)
From: Alan Stern <stern@rowland.harvard.edu>
To: Zdenek Kabelac <zkabelac@redhat.com>
cc: LKML <linux-kernel@vger.kernel.org>, <dianders@chromium.org>,
        <linux@roeck-us.net>, <gregkh@linuxfoundation.org>
Subject: Re: USB disk speed regression WD Elements - with bisect result
 22547c4cc4fe20698a6a85a55b8788859134b8e4
In-Reply-To: <695fe58e-1e66-a8f5-4232-3b7beedf9e4d@redhat.com>
Message-ID: <Pine.LNX.4.44L0.1707251019370.2256-100000@iolanthe.rowland.org>
MIME-Version: 1.0
Content-Type: TEXT/PLAIN; charset=US-ASCII
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 2971
Lines: 76

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.

Alan Stern