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

[Alan Stern]

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