Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751699AbdGYTuK (ORCPT ); Tue, 25 Jul 2017 15:50:10 -0400 Received: from iolanthe.rowland.org ([192.131.102.54]:49030 "HELO iolanthe.rowland.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with SMTP id S1753258AbdGYTuH (ORCPT ); Tue, 25 Jul 2017 15:50:07 -0400 Date: Tue, 25 Jul 2017 15:50:06 -0400 (EDT) From: Alan Stern X-X-Sender: stern@iolanthe.rowland.org To: Zdenek Kabelac cc: LKML , , , Subject: Re: USB disk speed regression WD Elements - with bisect result 22547c4cc4fe20698a6a85a55b8788859134b8e4 In-Reply-To: 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: 2350 Lines: 61 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 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. 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