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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Tue, 25 Jul 2017 17:03:02 +0200
From:   Zdenek Kabelac <zkabelac@...hat.com>
To:     Alan Stern <stern@...land.harvard.edu>
Cc:     LKML <linux-kernel@...r.kernel.org>, dianders@...omium.org,
        linux@...ck-us.net, gregkh@...uxfoundation.org
Subject: Re: USB disk speed regression WD Elements - with bisect result
 22547c4cc4fe20698a6a85a55b8788859134b8e4

Dne 25.7.2017 v 16:34 Zdenek Kabelac napsal(a):
> 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
> 

And in fact it's the very same commit - which adds this message
(just check current 4.13 with and without this commit reverted)

So here goes usbmon trace (aka  'cat /sys/kernel/debug/usb/usbmon/0u')
no other usb device has been touch so should not hopefully interfere here.

Trace is from 4.12 kernel - so it has reported  "not running at top speed"

Zdenek


View attachment "usbmon.txt" of type "text/plain" (87121 bytes)