Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752459AbdGZO27 (ORCPT ); Wed, 26 Jul 2017 10:28:59 -0400 Received: from iolanthe.rowland.org ([192.131.102.54]:48392 "HELO iolanthe.rowland.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1751874AbdGZO26 (ORCPT ); Wed, 26 Jul 2017 10:28:58 -0400 Date: Wed, 26 Jul 2017 10:28:57 -0400 (EDT) From: Alan Stern X-X-Sender: stern@iolanthe.rowland.org To: Guenter Roeck cc: Zdenek Kabelac , LKML , , Subject: Re: USB disk speed regression WD Elements - with bisect result 22547c4cc4fe20698a6a85a55b8788859134b8e4 In-Reply-To: <36de9669-aee1-bd3e-b36e-3ecb1a314efc@roeck-us.net> Message-ID: MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 2634 Lines: 65 On Tue, 25 Jul 2017, Guenter Roeck wrote: > 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 ? A little of both. When a reset completes, if the device does not follow the high-speed chirp protocol, the EHCI status registers show that the port is not enabled. When the driver sees that, it sets a bit that causes the connection to be moved over from the high-speed EHCI controller to the companion full-speed UHCI controller. The code that does this is in check_reset_complete() in ehci-hub.c. The logs showed the same thing in both kernels: When the reset completed, the port status showed no connection and not enabled. Nevertheless, one kernel switched the port over to the UHCI controller and the other kernel didn't. > 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. I don't think that is what happened. Alan Stern