Bug 12347

Created attachment 19619 [details]
dmesg > dmesg.log

Created attachment 19620 [details]
sudo lspci -vvnn > lspci-vvnn.log

Created attachment 19621 [details]
sudo lsusb -v > lsusb-v.log

As a side note (probably not connected) is that adding another USB storage device after the first USB storage device is working (but not at high speed) there is a difference between plain kernel and tainted kernel.

For tainted kernel (with both ATI/AMD fglrx and ath5k):
The first device is unmounted (disappears from screen) and it goes through the same scheme before being mounted again and then is the search for the newly inserted device started. This one will also be using ohci_hcd.

On plain kernel it works as expected, i.e the first device is not unmounted and the second device becomes usable after a while but still in low speed mode (ohci_hcd) 

Note to comment #4, This is not repeatable, when I went back to tainted kernel and performed the test again it worked the same way as the plain kernel.

Reply-To: akpm@linux-foundation.org


(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

On Fri,  2 Jan 2009 16:36:34 -0800 (PST)
bugme-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=12347
> 
>            Summary: ehci_hcd reverts to ohci_hcd under x86_64
>            Product: Other
>            Version: 2.5
>      KernelVersion:  2.6.27-9-generic #1 SMP Thu Nov 20 22:15:32 UTC 2008
>                     x86_64 GNU
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: Modules
>         AssignedTo: other_modules@kernel-bugs.osdl.org
>         ReportedBy: igor.lopez@bredband.net
> 
> 
> Latest working kernel version: Not tested on x86_64 earlier
> Earliest failing kernel version: 2.6.27-7 (have not tried earlier)
> Distribution: Ubuntu 8.10 AMD64, Fedora10 x86-64
> Hardware Environment: HP Pavilion dv7 Notebook PC 
> Software Environment: see above
> Problem Description: USB HD and USB memory sticks does not utilize ehci_hcd
> under 64 bit kernel (The very same devices works properly under i686 same
> kernel releases)
> It does not matter if I remove the ath5k and/or ATI/AMD fglrx module.
> 64 bit will not work but 32 bit will work.
> 
> 
> Steps to reproduce: Insert (any?? I have tried a few different versions of
> memory sticks and HD) USB memory stick or USB HD on above HW and fault will
> occur.
> 
> Note!! Test on untainted kernel was only performed on 2.26.27.7 and if needed
> I
> can perform the test without proprietary modules 0n 2.26.27.9.
> 
> I did not find a way of attaching normal debug info so they are included as
> plain text with the following markers and taken from the Ubuntu dist:
>  #uname
>  #version
>  #dmesg (added in following due to size restrict on comment)
>  #lspci (added in following due to size restrict on comment)
>  #lsusb (added in following due to size restrict on comment)
> 
> #uname
>  uname -a > uname-a.log
> Linux lopezdev 2.6.27-9-generic #1 SMP Thu Nov 20 22:15:32 UTC 2008 x86_64
> GNU/Linux
>
> ------------------------------------------------------------------------------
> 
> #version
>  cat /proc/version_signature > version.log
> Ubuntu 2.6.27-9.19-generic
>
> ------------------------------------------------------------------------------

On Mon, 5 Jan 2009, Andrew Morton wrote:

> > http://bugzilla.kernel.org/show_bug.cgi?id=12347
> > 
> >            Summary: ehci_hcd reverts to ohci_hcd under x86_64

You should collect a usbmon trace showing what happens when you first 
plug in or turn on the disk drive or memory stick.  See 
Documentation/usb/usbmon.txt for instructions.  Attach the usbmon log 
to the bug report and post a reply to this email so we will know about 
it.

Alan Stern

Created attachment 19763 [details]
Excerpt out of kern.log with kernel compiled with USB DEBUG

Created attachment 19764 [details]
config for USB DEBUG kernel

2009/1/12 <bugme-daemon@bugzilla.kernel.org>
>
> http://bugzilla.kernel.org/show_bug.cgi?id=12347
>
>
>
>
>
> ------- Comment #7 from stern@rowland.harvard.edu  2009-01-12 13:06 -------
> On Mon, 5 Jan 2009, Andrew Morton wrote:
>
> > > http://bugzilla.kernel.org/show_bug.cgi?id=12347
> > >
> > >            Summary: ehci_hcd reverts to ohci_hcd under x86_64
>
> You should collect a usbmon trace showing what happens when you first
> plug in or turn on the disk drive or memory stick.  See
> Documentation/usb/usbmon.txt for instructions.  Attach the usbmon log
> to the bug report and post a reply to this email so we will know about
> it.
>
> Alan Stern
>

Hi, I have just attached an excerpt out of the kern.log with a kernel
build with USB DEBUG turned on (see attached config.core2 for complete
kernel config)
Row: 4573,   Jan  4 21:41:34 lopezdev kernel: [  286.613525] ehci_hcd
0000:00:12.2: GetStatus port 5 status 001803 POWER sig=j CSC CONNECT
Row: 4615,   Jan  4 21:41:35 lopezdev kernel: [  287.150756] USB Mass
Storage support registered.
Row: 4616,   Jan  4 21:41:35 lopezdev kernel: [  287.154373]
usb-storage: *** thread sleeping.
Row: 4677,   Jan  4 21:41:40 lopezdev kernel: [  292.148184]
usb-storage: usb_stor_control_msg: rq=fe rqtype=a1 value=0000 index=00
len=1
Row: 4682,   Jan  4 21:41:40 lopezdev kernel: [  292.150780]
usb-storage: *** thread awakened.
Row: 4891,   Jan  4 21:41:40 lopezdev kernel: [  292.251970] sd
8:0:0:0: [sdb] Attached SCSI disk
Row: 5521,   Jan  4 21:42:10 lopezdev kernel: [  322.432132]
usb-storage: command_abort called
Row: 5534,   Jan  4 21:42:10 lopezdev kernel: [  322.556069] usb 5-5:
reset high speed USB device using ehci_hcd and address 5
Row: 5595,   Jan  4 21:42:15 lopezdev kernel: [  327.568132] usb 5-5:
usb-storage timed out on ep0in len=0/64

Plus more intresting reading further down in the log.

Alan wants me to do a usbmon trace which I will read up on but don't
know when it will be ready.

Igor Lumpus

Created attachment 19777 [details]
 sudo cat /sys/kernel/debug/usbmon/2u > usbmon.log

Performed a usbmon log according to the Linux Kernel Documentation

2009/1/12 Igor Lopez <igor.lopez@bredband.net>:
> 2009/1/12 <bugme-daemon@bugzilla.kernel.org>
>>
>> http://bugzilla.kernel.org/show_bug.cgi?id=12347
>>
>>
>>
>>
>>
>> ------- Comment #7 from stern@rowland.harvard.edu  2009-01-12 13:06 -------
>> On Mon, 5 Jan 2009, Andrew Morton wrote:
>>
>> > > http://bugzilla.kernel.org/show_bug.cgi?id=12347
>> > >
>> > >            Summary: ehci_hcd reverts to ohci_hcd under x86_64
>>
>> You should collect a usbmon trace showing what happens when you first
>> plug in or turn on the disk drive or memory stick.  See
>> Documentation/usb/usbmon.txt for instructions.  Attach the usbmon log
>> to the bug report and post a reply to this email so we will know about
>> it.
>>
>> Alan Stern
>>
>
> Hi, I have just attached an excerpt out of the kern.log with a kernel
> build with USB DEBUG turned on (see attached config.core2 for complete
> kernel config)
> Row: 4573,   Jan  4 21:41:34 lopezdev kernel: [  286.613525] ehci_hcd
> 0000:00:12.2: GetStatus port 5 status 001803 POWER sig=j CSC CONNECT
> Row: 4615,   Jan  4 21:41:35 lopezdev kernel: [  287.150756] USB Mass
> Storage support registered.
> Row: 4616,   Jan  4 21:41:35 lopezdev kernel: [  287.154373]
> usb-storage: *** thread sleeping.
> Row: 4677,   Jan  4 21:41:40 lopezdev kernel: [  292.148184]
> usb-storage: usb_stor_control_msg: rq=fe rqtype=a1 value=0000 index=00
> len=1
> Row: 4682,   Jan  4 21:41:40 lopezdev kernel: [  292.150780]
> usb-storage: *** thread awakened.
> Row: 4891,   Jan  4 21:41:40 lopezdev kernel: [  292.251970] sd
> 8:0:0:0: [sdb] Attached SCSI disk
> Row: 5521,   Jan  4 21:42:10 lopezdev kernel: [  322.432132]
> usb-storage: command_abort called
> Row: 5534,   Jan  4 21:42:10 lopezdev kernel: [  322.556069] usb 5-5:
> reset high speed USB device using ehci_hcd and address 5
> Row: 5595,   Jan  4 21:42:15 lopezdev kernel: [  327.568132] usb 5-5:
> usb-storage timed out on ep0in len=0/64
>
> Plus more intresting reading further down in the log.
>
> Alan wants me to do a usbmon trace which I will read up on but don't
> know when it will be ready.
>
> Igor Lumpus
>

I have now made a usbmon log according to the documentation. I did it
with the generic Kernel shipped with Ubuntu AMD64 and the result looks
similar as the information from my core2 kernel with USB_DEBUG in the
config. (but different format of course)

Igor Lumpus

On Tue, 13 Jan 2009, Igor Lopez wrote:

> I have now made a usbmon log according to the documentation. I did it
> with the generic Kernel shipped with Ubuntu AMD64 and the result looks
> similar as the information from my core2 kernel with USB_DEBUG in the
> config. (but different format of course)

The logs show two major problems.  The first is a problem with your 
disk drive.  It was working fine with EHCI until the system tried to 
read the last sector on the disk.  At that point the drive died, and it 
didn't respond again until the computer began communicating using OHCI.  
Oddly enough, when the system tried to read the last sector again 
(using OHCI this time) the drive worked fine.

So your Western Digital drive (or its USB interface) has a bug.  Can 
you collect the equivalent kern.log for the USB flash drive?  I 
wouldn't expect two different sorts of devices to have the same bug.

The other problem is what makes your logs so big.  All those lines 
like:

Jan  4 21:41:34 lopezdev kernel: [  286.344268] hub 1-0:1.0: state 7 ports 3 chg 0000 evt 0000
Jan  4 21:41:34 lopezdev kernel: [  286.344289] hub 2-0:1.0: state 7 ports 3 chg 0000 evt 0000
Jan  4 21:41:34 lopezdev kernel: [  286.344299] hub 3-0:1.0: state 7 ports 3 chg 0000 evt 0000

should not be there.  I have no idea why you're getting them.  Can you 
try running 2.6.28 to see if the same thing happens?

Alan Stern

2009/1/13 Alan Stern <stern@rowland.harvard.edu>:
> The logs show two major problems.  The first is a problem with your
> disk drive.
It does not matter which USB Disk Drive (I have tried a few different
ones) I use, and it happens only with 64 bit kernels, under 32 bit all
works as expected so it sounds more like that the 64 bit kernel is
more sensitive to the drives I have tried than the 32 bit kernel is..

>It was working fine with EHCI until the system tried to
> read the last sector on the disk.  At that point the drive died, and it
> didn't respond again until the computer began communicating using OHCI.
> Oddly enough, when the system tried to read the last sector again
> (using OHCI this time) the drive worked fine.
Is this a timing issue where 64 bit kernel somehow is more sensitive
due to the way the processor works running 64 bit?

>
> So your Western Digital drive (or its USB interface) has a bug.  Can
> you collect the equivalent kern.log for the USB flash drive?  I
> wouldn't expect two different sorts of devices to have the same bug.
I'll do it for a few different ones.

>
> The other problem is what makes your logs so big.  All those lines
> like:
>
> Jan  4 21:41:34 lopezdev kernel: [  286.344268] hub 1-0:1.0: state 7 ports 3
> chg 0000 evt 0000
> Jan  4 21:41:34 lopezdev kernel: [  286.344289] hub 2-0:1.0: state 7 ports 3
> chg 0000 evt 0000
> Jan  4 21:41:34 lopezdev kernel: [  286.344299] hub 3-0:1.0: state 7 ports 3
> chg 0000 evt 0000
>
> should not be there.  I have no idea why you're getting them.  Can you
> try running 2.6.28 to see if the same thing happens?
How do I get a 2.6.28 64 bit kernel to my Ubuntu dist?
I have only built one Kernel so far and that was with a recepie found
on the net and it was from Ubunbtu repository.
Some advice would be apreciated.

>
> Alan Stern
>

Igor Lumpus

On Wed, 14 Jan 2009, Igor Lopez wrote:

> 2009/1/13 Alan Stern <stern@rowland.harvard.edu>:
> > The logs show two major problems.  The first is a problem with your
> > disk drive.
> It does not matter which USB Disk Drive (I have tried a few different
> ones) I use, and it happens only with 64 bit kernels, under 32 bit all
> works as expected so it sounds more like that the 64 bit kernel is
> more sensitive to the drives I have tried than the 32 bit kernel is..

I don't know why that should be.

> >It was working fine with EHCI until the system tried to
> > read the last sector on the disk.  At that point the drive died, and it
> > didn't respond again until the computer began communicating using OHCI.
> > Oddly enough, when the system tried to read the last sector again
> > (using OHCI this time) the drive worked fine.
> Is this a timing issue where 64 bit kernel somehow is more sensitive
> due to the way the processor works running 64 bit?

I don't think so, but I don't know for sure.  Timing sensitivity of the
kernel doesn't really matter here; the computer waited for 30 seconds
for the drive to respond!

> > The other problem is what makes your logs so big.  All those lines
> > like:
> >
> > Jan  4 21:41:34 lopezdev kernel: [  286.344268] hub 1-0:1.0: state 7 ports
> 3 chg 0000 evt 0000
> > Jan  4 21:41:34 lopezdev kernel: [  286.344289] hub 2-0:1.0: state 7 ports
> 3 chg 0000 evt 0000
> > Jan  4 21:41:34 lopezdev kernel: [  286.344299] hub 3-0:1.0: state 7 ports
> 3 chg 0000 evt 0000
> >
> > should not be there.  I have no idea why you're getting them.  Can you
> > try running 2.6.28 to see if the same thing happens?
> How do I get a 2.6.28 64 bit kernel to my Ubuntu dist?
> I have only built one Kernel so far and that was with a recepie found
> on the net and it was from Ubunbtu repository.
> Some advice would be apreciated.

I can't help you there.  You'll have to ask a Ubuntu person for advice 
on building Ubuntu-specific kernels.

But maybe you can take your old .config file and use it with a vanilla 
kernel downloaded from www.kernel.org.

Alan Stern

Created attachment 19854 [details]
usbmon log for cruzer usb memory stick

Created attachment 19855 [details]
usbmon log for a HP Media Drive USB HD

Created attachment 19856 [details]
usbmon log for kingston usb memory stick

Created attachment 19857 [details]
usbmon log for ONE TECHNOLOGIE USB HD

I have now attached four more usbmon logs with different memory sticks
and different USB HD.
They all show the same symptom, takes for ever to be mounted and when
mounted it is the ohci_hcd being used.

Can you have a look at them Alan and see if it something common between them?

I find it very unlikely that the devices are all 'Bad' and since they
work flawlessly under 32bit kernel I am assuming that the 64bit kernel
has a bug (maybe due to my HW but it is the same HW when running 32
bit that works....)

I will try to get the 2.6.28 kernel built in a 64 bit version but it
may take time and if it works it would still be beneficial to find out
what changes that made it work since there might be a systematic
design construct causing it to misbehave under 64bit.

Igor Lumpus

Ok,

I have now tested with latest kernel for Ubuntu:
  2.6.28-4-generic #11-Ubuntu SMP Fri Jan 16 21:50:52 UTC 2009 x86_64 GNU/Linux

and here it works with ehci_hcd directly (5 seconds before insert of
USB until mounted)
Unfortunately the usbmon module was not availible but I do not know
how that could
help out finding the root cause it did not work in 2.6.27-9 (or -7) kernel.

I would rather run a patched 2.6.27-9 kernel due to not (yet) having a
proper fglrx
for 2.6.28-4 kernel.

Igor Lumpus

The bug is not existing in latest 64 bit Kernel, 
Tested on Ubuntu 2.6.28-4-generic where all USB devices
worked as expected.