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

From: Alan Stern
Date: Wed Jul 26 2017 - 10:29:03 EST


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