Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751699AbdGZCdn (ORCPT ); Tue, 25 Jul 2017 22:33:43 -0400 Received: from bh-25.webhostbox.net ([208.91.199.152]:52927 "EHLO bh-25.webhostbox.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751524AbdGZCdm (ORCPT ); Tue, 25 Jul 2017 22:33:42 -0400 Subject: Re: USB disk speed regression WD Elements - with bisect result 22547c4cc4fe20698a6a85a55b8788859134b8e4 To: Alan Stern , Zdenek Kabelac Cc: LKML , dianders@chromium.org, gregkh@linuxfoundation.org References: From: Guenter Roeck Message-ID: <36de9669-aee1-bd3e-b36e-3ecb1a314efc@roeck-us.net> Date: Tue, 25 Jul 2017 19:33:39 -0700 User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Thunderbird/52.2.1 MIME-Version: 1.0 In-Reply-To: Content-Type: text/plain; charset=utf-8; format=flowed Content-Language: en-US Content-Transfer-Encoding: 7bit X-Authenticated_sender: linux@roeck-us.net X-OutGoing-Spam-Status: No, score=-1.0 X-AntiAbuse: This header was added to track abuse, please include it with any abuse report X-AntiAbuse: Primary Hostname - bh-25.webhostbox.net X-AntiAbuse: Original Domain - vger.kernel.org X-AntiAbuse: Originator/Caller UID/GID - [47 12] / [47 12] X-AntiAbuse: Sender Address Domain - roeck-us.net X-Get-Message-Sender-Via: bh-25.webhostbox.net: authenticated_id: linux@roeck-us.net X-Authenticated-Sender: bh-25.webhostbox.net: linux@roeck-us.net X-Source: X-Source-Args: X-Source-Dir: Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 3228 Lines: 81 On 07/25/2017 12:50 PM, Alan Stern wrote: > On Tue, 25 Jul 2017, Zdenek Kabelac wrote: > >> Dne 25.7.2017 v 19:02 Alan Stern napsal(a): >>> On Tue, 25 Jul 2017, Zdenek Kabelac wrote: >>> >>>> 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" >>> >>> Can you collect an equivalent trace under 4.8? >>> >>> Alan Stern >>> >> >> Hi >> >> >> Sure - no pb. >> >> Just attached & detached USB disk in this trace > > This is really peculiar. The only difference is that the 4.12 trace > shows an extra 250 ms delay (including two extra Get-Port-Status Most likely we are now catching the long reset timeout. HUB_LONG_RESET_TIME is 200 ms. It looks like the code is catching exactly the condition addressed in my patch, ie USB_PORT_STAT_RESET is cleared but USB_PORT_STAT_CONNECTION is not yet set. hub_port_wait_reset() will now wait for USB_PORT_STAT_CONNECTION, which it didn't do before. > requests) compared to the 4.8 trace. I honestly can't tell what could > be causing the switch from high speed to full speed, or why it would > happen in one case but not the other. > We talked about this today. What is causing the switch from high speed to full speed ? Is this triggered by the kernel, or by the USB controller ? If it is triggered by the USB controller, maybe the changed timing around repeated hub resets, either in combination with an additional hub reset or in combination with fewer resets, results in the full speed connection. That is just a wild guess, of course. Guenter > It's obvious that _something_ is confusing the USB hardware in the disk > drive. This shows up in both traces: After you unplug and replug the > drive, it initially connects at high-speed and then disconnects itself > before the computer can communicate with it. Then a second connection > occurs. For example, in the 4.8 log: > > 08:18 usb 2-2: USB disconnect, device number 2 > 08:25 usb 2-2: new high-speed USB device number 3 using ehci-pci > 08:26 usb 2-2: new high-speed USB device number 4 using ehci-pci > > If the drive were working entirely correctly, it wouldn't do that. > > We could continue futzing around with hardware and driver tests for a > long time. But there may be a shortcut: If you have a USB hub, you > could try attaching the drive through it. It's entirely possible that > this will fix the problem. > > If not, you'll have to start doing some very detailed tests. As a > start, you can enable debugging for the usbcore and ehci_hcd drivers > immediately before the test: > > echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control > echo 'module ehci_hcd =p' >/sys/kernel/debug/dynamic_debug/control > dmesg -C > > Then after the test, see what shows up in the dmesg output. And again, > we'll want to do a comparison. In fact, 4.12 with and without the > commit you identified would make a better comparison than 4.12 vs. 4.8. > > Alan Stern > >