DMARC-Filter: OpenDMARC Filter v1.3.2 mx1.redhat.com 16CAA8F31D
Subject: Re: USB disk speed regression WD Elements - with bisect result
 22547c4cc4fe20698a6a85a55b8788859134b8e4
To: Alan Stern <stern@rowland.harvard.edu>
Cc: LKML <linux-kernel@vger.kernel.org>, dianders@chromium.org,
        linux@roeck-us.net, gregkh@linuxfoundation.org
References: <Pine.LNX.4.44L0.1707251019370.2256-100000@iolanthe.rowland.org>
From: Zdenek Kabelac <zkabelac@redhat.com>
Organization: Red Hat
Message-ID: <9525f457-5232-16c7-816c-c9a53c881325@redhat.com>
Date: Tue, 25 Jul 2017 16:34:09 +0200
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101
 Thunderbird/52.2.0
MIME-Version: 1.0
In-Reply-To: <Pine.LNX.4.44L0.1707251019370.2256-100000@iolanthe.rowland.org>
Content-Type: text/plain; charset=iso-8859-2; format=flowed
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Sender: linux-kernel-owner@vger.kernel.org
Content-Length: 3466
Lines: 92

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