Bug 6994 - snd_usb_audio corrupts usb-bus with uhci_hcd
Summary: snd_usb_audio corrupts usb-bus with uhci_hcd
Status: REJECTED INVALID
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: i386 Linux
: P2 normal
Assignee: Greg Kroah-Hartman
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-08-12 14:59 UTC by Felix Schueller
Modified: 2006-08-30 01:11 UTC (History)
1 user (show)

See Also:
Kernel Version: 2.6.16 2.6.17.8 2.6.18-rc4
Subsystem:
Regression: ---
Bisected commit-id:


Attachments
copy of /sys/kernel/debug/uhci/0000:00:07.2 after unpluging the speaker (2.03 KB, text/plain)
2006-08-14 09:37 UTC, Felix Schueller
Details
copy of /sys/kernel/debug/uhci/0000:00:07.2 after pluging in the stick (2.63 KB, text/plain)
2006-08-14 09:38 UTC, Felix Schueller
Details
Improved frame-related diagnostics (1.62 KB, patch)
2006-08-14 14:12 UTC, Alan Stern
Details | Diff
copy of /sys/kernel/debug/uhci/0000:00:07.2 after unpluging the speaker 2 (2.03 KB, text/plain)
2006-08-15 14:06 UTC, Felix Schueller
Details
8786: copy of /sys/kernel/debug/uhci/0000:00:07.2 after pluging in the stick 2 (2.63 KB, text/plain)
2006-08-15 14:09 UTC, Felix Schueller
Details
Diagnostic patch for UHCI (3.88 KB, patch)
2006-08-16 07:34 UTC, Alan Stern
Details | Diff
copy of /sys/kernel/debug/uhci/0000:00:07.2 during test tone (3.89 KB, text/plain)
2006-08-17 00:00 UTC, Felix Schueller
Details
copy of /sys/kernel/debug/uhci/0000:00:07.2 after test tone stops (3.92 KB, text/plain)
2006-08-17 00:01 UTC, Felix Schueller
Details
copy of /sys/kernel/debug/uhci/0000:00:07.2 after plugout in the speaker (1.68 KB, text/plain)
2006-08-17 00:02 UTC, Felix Schueller
Details
output of dmesg (1.86 KB, text/plain)
2006-08-17 00:04 UTC, Felix Schueller
Details
/sys/kernel/debug/usbmon/1t (bzip2) (103.01 KB, application/x-bzip2)
2006-08-17 00:09 UTC, Felix Schueller
Details
Don't stop when an ISO packet gets an error (396 bytes, patch)
2006-08-17 14:05 UTC, Alan Stern
Details | Diff
/sys/kernel/debug/usbmon/1t 2. version (bzip2) (151.85 KB, application/x-bzip2)
2006-08-18 05:41 UTC, Felix Schueller
Details
Don't stop on ISO error and early rejection of late ISO URBs (1.80 KB, patch)
2006-08-18 08:47 UTC, Alan Stern
Details | Diff
/sys/kernel/debug/usbmon/1t 3. version (bzip2) (187.03 KB, application/x-bzip2)
2006-08-19 13:34 UTC, Felix Schueller
Details

Description Felix Schueller 2006-08-12 14:59:15 UTC
Most recent kernel where this bug did not occur: Don't know, I've just bought
the speaker

Distribution: Linux from scratch

Hardware Environment: 
USB Controller: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (rev 02)
Speaker: Typhoon notebook USB speakers (C-Media USB Audio) Specker with an
integrated usb-soundcard

Software Environment: alsa-lib-1.0.11, alsa-utils-1.0.11, libusb-0.1.12

Problem Description:

After pluging in the speakers snd_usb_audio is loaded, and with "speaker-test -t
sin" one gets an nice tone. But after a short time (or trying to andjust the
volume) the tone stops, and the usb-bus can not longer used.

If you need additional infos (parts of the kernel config, etc), just email me.

/var/log/messages (2.6.17.8):

Aug 12 23:02:20 frodo kernel: usb 1-2: new full speed USB device using uhci_hcd
and address 4
Aug 12 23:02:20 frodo kernel: usb 1-2: Product: C-Media USB Audio       
Aug 12 23:02:20 frodo kernel: usb 1-2: Manufacturer: C-Media INC.
Aug 12 23:02:20 frodo kernel: usb 1-2: configuration #1 chosen from 1 choice
Aug 12 23:02:23 frodo kernel: usbcore: registered new driver snd-usb-audio
# 1. run of "speaker-test -t sin"
# 2. run of "speaker-test -t sin"
Aug 12 23:03:08 frodo kernel: 4:1:1: usb_set_interface failed
#unplug the speacker
Aug 12 23:08:09 frodo kernel: usb 1-2: USB disconnect, address 4
#pluging in an usb-stick (usb-storage)
Aug 12 23:33:43 frodo kernel: usb 1-2: new full speed USB device using uhci_hcd
and address 5
Aug 12 23:33:46 frodo kernel: usb 1-2: device descriptor read/64, error -110
Aug 12 23:34:01 frodo kernel: usb 1-2: device descriptor read/64, error -110
# second try
Aug 12 23:34:01 frodo kernel: usb 1-2: new full speed USB device using uhci_hcd
and address 6
Aug 12 23:34:05 frodo kernel: usb 1-2: device descriptor read/64, error -110

/var/log/debug (2.6.17.8):

Aug 12 23:02:19 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 12 23:02:19 frodo kernel: uhci_hcd 0000:00:07.2: port 2 portsc 0093,00
Aug 12 23:02:19 frodo kernel: hub 1-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
Aug 12 23:02:20 frodo kernel: hub 1-0:1.0: debounce: port 2: total 100ms stable
100ms status 0x101
Aug 12 23:02:20 frodo kernel: usb 1-2: ep0 maxpacket = 8
Aug 12 23:02:20 frodo kernel: usb 1-2: skipped 4 descriptors after interface
Aug 12 23:02:20 frodo kernel: usb 1-2: skipped 2 descriptors after interface
Aug 12 23:02:20 frodo kernel: usb 1-2: skipped 1 descriptor after endpoint
Aug 12 23:02:20 frodo kernel: usb 1-2: default language 0x0409
Aug 12 23:02:20 frodo kernel: usb 1-2: new device strings: Mfr=1, Product=2,
SerialNumber=0
Aug 12 23:02:20 frodo kernel: usb 1-2: uevent
Aug 12 23:02:20 frodo kernel: usb 1-2: adding 1-2:1.0 (config #1, interface 0)
Aug 12 23:02:20 frodo kernel: usb 1-2:1.0: uevent
Aug 12 23:02:20 frodo kernel: usb 1-2: adding 1-2:1.1 (config #1, interface 1)
Aug 12 23:02:20 frodo kernel: usb 1-2:1.1: uevent
Aug 12 23:02:20 frodo kernel: drivers/usb/core/inode.c: creating file '004'
Aug 12 23:02:20 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 12 23:02:23 frodo kernel: snd-usb-audio 1-2:1.0: usb_probe_interface
Aug 12 23:02:23 frodo kernel: snd-usb-audio 1-2:1.0: usb_probe_interface - got id
Aug 12 23:02:26 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 12 23:02:26 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 12 23:02:26 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 12 23:02:28 frodo last message repeated 2027 times
Aug 12 23:02:43 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 12 23:02:43 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 12 23:02:43 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 12 23:02:46 frodo last message repeated 2889 times
Aug 12 23:02:46 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 12 23:02:46 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 12 23:02:46 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 12 23:02:46 frodo last message repeated 24 times
Aug 12 23:02:56 frodo kernel: usb 1-2: speaker-test timed out on ep0out len=0/0
Aug 12 23:03:08 frodo kernel: usb 1-2: speaker-test timed out on ep0out len=0/0
Aug 12 23:08:09 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 12 23:08:09 frodo kernel: uhci_hcd 0000:00:07.2: port 2 portsc 008a,00
Aug 12 23:08:09 frodo kernel: hub 1-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
Aug 12 23:08:09 frodo kernel: usb 1-2: usb_disable_device nuking all URBs
Aug 12 23:08:09 frodo kernel: usb 1-2: unregistering interface 1-2:1.0
Aug 12 23:31:39 frodo kernel: usb 1-2:1.0: uevent
Aug 12 23:31:39 frodo kernel: usb 1-2: unregistering interface 1-2:1.1
Aug 12 23:31:39 frodo kernel: usb 1-2:1.1: uevent
Aug 12 23:31:39 frodo kernel: usb 1-2: unregistering device
Aug 12 23:31:39 frodo kernel: usb 1-2: uevent
Aug 12 23:31:39 frodo kernel: hub 1-0:1.0: debounce: port 2: total 100ms stable
100ms status 0x100
Aug 12 23:33:43 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 12 23:33:43 frodo kernel: uhci_hcd 0000:00:07.2: port 2 portsc 0093,00
Aug 12 23:33:43 frodo kernel: hub 1-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
Aug 12 23:33:43 frodo kernel: hub 1-0:1.0: debounce: port 2: total 100ms stable
100ms status 0x101
Aug 12 23:33:44 frodo kernel: usb 1-2: khubd timed out on ep0in len=0/64
Aug 12 23:34:15 frodo last message repeated 10 times
Aug 12 23:34:20 frodo kernel: usb 1-2: khubd timed out on ep0in len=0/64
Aug 12 23:34:20 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004

/var/log/messages (2.6.18-rc4):

Aug 10 16:34:35 frodo kernel: usb 1-2: new full speed USB device using uhci_hcd
and address 4
Aug 10 16:34:35 frodo kernel: usb 1-2: Product: C-Media USB Audio       
Aug 10 16:34:35 frodo kernel: usb 1-2: Manufacturer: C-Media INC.
Aug 10 16:34:35 frodo kernel: usb 1-2: configuration #1 chosen from 1 choice
Aug 10 16:34:38 frodo kernel: usbcore: registered new driver snd-usb-audio
# "speaker-test -tsin"
Aug 10 16:34:50 frodo kernel: playback drain error (DMA or IRQ trouble?)
Aug 10 16:35:10 frodo last message repeated 2 times
# unpluging the speaker
Aug 10 16:42:49 frodo kernel: usb 1-2: USB disconnect, address 4
# repluging
Aug 10 16:43:27 frodo kernel: usb 1-2: new full speed USB device using uhci_hcd
and address 5
Aug 10 16:43:30 frodo kernel: usb 1-2: device descriptor read/64, error -110

/var/log/debug (2.6.18-rc4)

Aug 10 16:34:34 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 10 16:34:34 frodo kernel: uhci_hcd 0000:00:07.2: port 2 portsc 0093,00
Aug 10 16:34:34 frodo kernel: hub 1-0:1.0: port 2, status 0101, change 0001, 12 Mb/s
Aug 10 16:34:35 frodo kernel: hub 1-0:1.0: debounce: port 2: total 100ms stable
100ms status 0x101
Aug 10 16:34:35 frodo kernel: usb 1-2: ep0 maxpacket = 8
Aug 10 16:34:35 frodo kernel: usb 1-2: skipped 4 descriptors after interface
Aug 10 16:34:35 frodo kernel: usb 1-2: skipped 2 descriptors after interface
Aug 10 16:34:35 frodo kernel: usb 1-2: skipped 1 descriptor after endpoint
Aug 10 16:34:35 frodo kernel: usb 1-2: default language 0x0409
Aug 10 16:34:35 frodo kernel: usb 1-2: new device strings: Mfr=1, Product=2,
SerialNumber=0
Aug 10 16:34:35 frodo kernel: usb 1-2: uevent
Aug 10 16:34:35 frodo kernel: usb 1-2: adding 1-2:1.0 (config #1, interface 0)
Aug 10 16:34:35 frodo kernel: usb 1-2:1.0: uevent
Aug 10 16:34:35 frodo kernel: usb 1-2: adding 1-2:1.1 (config #1, interface 1)
Aug 10 16:34:35 frodo kernel: usb 1-2:1.1: uevent
Aug 10 16:34:35 frodo kernel: drivers/usb/core/inode.c: creating file '004'
Aug 10 16:34:35 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 10 16:34:37 frodo kernel: snd-usb-audio 1-2:1.0: usb_probe_interface
Aug 10 16:34:37 frodo kernel: snd-usb-audio 1-2:1.0: usb_probe_interface - got id
Aug 10 16:34:37 frodo kernel:  usbdev1.4_ep06: ep_device_release called for
usbdev1.4_ep06
Aug 10 16:34:38 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 10 16:34:38 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 10 16:34:38 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 10 16:34:49 frodo last message repeated 1916 times
Aug 10 16:34:50 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 10 16:34:50 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 10 16:34:50 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 10 16:35:00 frodo last message repeated 40 times
Aug 10 16:35:00 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 10 16:35:00 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 10 16:35:00 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 10 16:35:10 frodo last message repeated 40 times
Aug 10 16:35:10 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
796 + 157 = 953 usec
Aug 10 16:35:10 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
953 + 157 = 1110 usec
Aug 10 16:35:10 frodo kernel: usb 1-2: usb_check_bandwidth would have FAILED:
1110 + 157 = 1267 usec
Aug 10 16:35:17 frodo last message repeated 27 times
Aug 10 16:35:22 frodo kernel: usb 1-2: speaker-test timed out on ep0out len=-8/0

Output of the second speaker-test run:

speaker-test 1.0.11

Playback device is default
Stream parameters are 48000Hz, S16_LE, 1 channels
Sine wave rate is 440.0000Hz
Rate set to 48000Hz (requested 48000Hz)
Buffer size range from 96 to 262144
Period size range from 48 to 131072
Using max buffer size 262144
Periods = 4
was set period_size = 65536
was set buffer_size = 262144
Unable to set hw params for playback: Input/output error
Setting of hwparams failed: Input/output error

The speakers work on an other box (ehci_hcd/ohci_hcd):

Aug 12 23:52:34 luggage kernel: ohci_hcd 0000:00:02.1: wakeup
Aug 12 23:52:34 luggage kernel: usb 2-4: new full speed USB device using
ohci_hcd and address 2
Aug 12 23:52:35 luggage kernel: usb 2-4: configuration #1 chosen from 1 choice
Aug 12 23:52:36 luggage kernel: usbcore: registered new driver snd-usb-audio
Comment 1 Alan Stern 2006-08-13 12:15:23 UTC
One thing here looks very suspicious.  What's up in the second log
(/var/log/debug from 2.6.17.8) with the long delay between 23:08:09 and
23:31:39?  Was the usb-audio driver just spinning its wheels, or was it
something more sinister?  Unfortunately the log from 2.6.18-rc4 didn't include
the analogous time period so we can't compare against it.

What happens if you don't run the speaker-test program, but just unplug the
speaker?  Can you then plug in the USB stick successfully?

Something to try:  Set CONFIG_DEBUG_FS in the kernel configuration.  Then before
repeating your test, do

    mount -t debugfs none /sys/kernel/debug
    echo 2 >/sys/module/uhci_hcd/parameters/debug

Then after unplugging the speaker but before plugging in anything else, make a
copy of /sys/kernel/debug/uhci/0000:00:07.2.  Make another copy of that file
after plugging in the USB stick, and attach both copies here.

Just to keep things simple, let's focus only on 2.6.18-rc4 for now.
Comment 2 Felix Schueller 2006-08-14 09:37:32 UTC
Created attachment 8785 [details]
copy of /sys/kernel/debug/uhci/0000:00:07.2 after unpluging the speaker
Comment 3 Felix Schueller 2006-08-14 09:38:55 UTC
Created attachment 8786 [details]
copy of /sys/kernel/debug/uhci/0000:00:07.2 after pluging in the stick
Comment 4 Felix Schueller 2006-08-14 09:44:01 UTC
> One thing here looks very suspicious.  What's up in the second log
> (/var/log/debug from 2.6.17.8) with the long delay between 23:08:09 and
> 23:31:39?  Was the usb-audio driver just spinning its wheels, or was it
> something more sinister?

Sorry for that, thats my fault. I started to write the bugreport but forgot that
alsamixergui was still runing. I think at 23:31:39 alsamixergui was killed.

> What happens if you don't run the speaker-test program, but just unplug the
> speaker?  Can you then plug in the USB stick successfully?

Yes, then I also can plug the speaker back.

The files are attatched. Produced by: Reboot, Pluging the speaker in,
speaker-test, ^C, unplug the speaker, cp, plugin the stick.
Comment 5 Alan Stern 2006-08-14 14:12:26 UTC
Created attachment 8789 [details]
Improved frame-related diagnostics

Please try out the attached diagnostic patch.  It tests for certain kinds of
errors that the current driver doesn't look for, errors which you may be
getting.

After applying the patch, run the same test as before.	If the first file copy
(before plugging in the stick) contains a bunch of warnings about links not
matching, then there's no need to make the second copy.
Comment 6 Felix Schueller 2006-08-15 14:06:07 UTC
Created attachment 8795 [details]
copy of /sys/kernel/debug/uhci/0000:00:07.2 after unpluging the speaker 2
Comment 7 Felix Schueller 2006-08-15 14:09:09 UTC
Created attachment 8796 [details]
8786: copy of /sys/kernel/debug/uhci/0000:00:07.2 after pluging in the stick 2

No big changes, afais. I doublechecked that the Patch is applied.
Comment 8 Alan Stern 2006-08-16 07:34:56 UTC
Created attachment 8799 [details]
Diagnostic patch for UHCI

I can tell this is going to be a hard problem to solve.  :-(  The logs didn't
point to anything in particular, but they did show the controller was in a
weird state.

The attached patch is an improved version of the previous one.	Along with the
new diagnostics, it also suppresses all those "usb_check_bandwidth" messages
that clutter up the system log.

In addition to the usual copies, this time try making a copy of the file while
the test tone is playing, and then again after the test tone fizzles out but
before you unplug the device.  You don't have any other USB devices attached,
do you?  If yes, it would be best to unplug them before running the test.

Also attach the dmesg output for the test.  (You can clear the dmesg buffer
before starting the test by doing "dmesg -c >/dev/null".)

Finally, it might help to see the output from usbmon throughout the test. 
There are instructions for running usbmon in the kernel source file
Documentation/usb/usbmon.txt.  To build usbmon you have to set CONFIG_USB_MON. 
The file you will want to cat is /sys/kernel/debug/usbmon/1t.
Comment 9 Felix Schueller 2006-08-16 13:54:02 UTC
I had a usb-hub and a cardreader connected in the other usb-port, and during the
first test i testet all combinations (speaker at hub, speaker alone, hub and
speaker at different ports) and got no change (no sound in all 3 settings) so i
thought that doesn't matter.

But now I have the following situation:

1. speaker only:

speacker-test give a tone, but stops after a while (specially if i work with the
machine). After unplug I can plug in any other device, this includes the
speaker, which are then functionable, again.

2. Speaker and some other devices:

Situation from the first report, but if I disconnect every device, the bus recovers.

Shame on me, I totally forgot the hub during writing the first bugreport, and
during the second test I don't want to change the setup. I still think it's a
bug, but my inital bugreport wasn't the best.
Comment 10 Alan Stern 2006-08-16 14:08:04 UTC
I thought that might happen.  When there are no devices attached, the driver
automatically stops the controller.  Then when you plug in a new device, the
controller is restarted and it works okay.  Apparently while the speaker-test
program runs, the controller gets into a state where it thinks it is running but
it doesn't actually do anything.  That's why I asked you to make copies of that
file while the program was running.  Stopping and restarting the controller gets
it going again.

But you're right, this is a bug.  Probably a bug in the driver, although just
possibly a bug in the hardware.  Have you tried using a 2.6.16 kernel?  There
was a significant change in uhci-hcd just before 2.6.17 came out, affecting
exactly this sort of operation.  There's a very good chance the change had an
error in it.  Not having any USB audio cards, I couldn't test it very well.
Comment 11 Felix Schueller 2006-08-17 00:00:05 UTC
Created attachment 8807 [details]
 copy of /sys/kernel/debug/uhci/0000:00:07.2 during test tone
Comment 12 Felix Schueller 2006-08-17 00:01:38 UTC
Created attachment 8808 [details]
copy of /sys/kernel/debug/uhci/0000:00:07.2 after test tone stops
Comment 13 Felix Schueller 2006-08-17 00:02:57 UTC
Created attachment 8809 [details]
copy of /sys/kernel/debug/uhci/0000:00:07.2 after plugout in the speaker
Comment 14 Felix Schueller 2006-08-17 00:04:26 UTC
Created attachment 8810 [details]
output of dmesg
Comment 15 Felix Schueller 2006-08-17 00:09:06 UTC
Created attachment 8811 [details]
/sys/kernel/debug/usbmon/1t (bzip2)
Comment 16 Felix Schueller 2006-08-17 01:29:08 UTC
Comment on attachment 8811 [details]
/sys/kernel/debug/usbmon/1t (bzip2)

I test the speaker with 2.6.16 later, I have to kompile the kernel for that, an
the machine ist not the fastest.
Comment 17 Felix Schueller 2006-08-17 10:36:42 UTC
The error is also reproducible with kernel version 2.6.16
Comment 18 Alan Stern 2006-08-17 14:02:47 UTC
The usbmon log is interesting.  Here's where the errors start occurring:

d3b406a0 390495195 C Zo:002:06 -63 64 >
d3b406a0 390495225 S Zo:002:06 -115 192 = 20c020c0 00c000c0 16c016c0 62c062c0
d3b40720 390496176 C Zo:002:06 -63 64 >
d3b40720 390496184 S Zo:002:06 -115 192 = e839e839 613b613b a83ca83c bb3dbb3d
d3b401a0 390497218 C Zo:002:06 -63 128 >
d3b401a0 390497248 S Zo:002:06 -115 192 = 30d430d4 93d193d1 1dcf1dcf d1ccd1cc
d3b40220 390522968 C Zo:002:06 -18 0

Those -63 values mean the USB controller couldn't read the data over the PCI bus
in time to send it out the USB bus.  The -18 error indicates that the controller
just stopped sending data entirely.

It's possible that your computer's PCI bus is getting saturated, but I think
it's more likely that the USB controller has a hardware problem.  The total
amount of data being sent isn't all that large (192 bytes every millisecond); I
see transfer rates higher than that all the time.  This could mean that the
controller really isn't working right.  It does not look like a problem in the
driver, after all.

Can you try out the speakers on a different Linux computer, hopefully one with a
UHCI controller?
Comment 19 Alan Stern 2006-08-17 14:05:50 UTC
Created attachment 8821 [details]
Don't stop when an ISO packet gets an error

On second reading, the usbmon log did show up a small bug in the driver.  It
didn't cause your problem, but I would like to make sure it gets fixed anyway. 


Please apply this patch (keep the other one too) and try the test again.  This
time I don't need to see the /sys/kernel/debug/uhci files; only the usbmon log
is important.
Comment 20 Felix Schueller 2006-08-18 05:41:03 UTC
Created attachment 8826 [details]
/sys/kernel/debug/usbmon/1t 2. version (bzip2)

Your Patch changes to little things:

The output of speakertest is a bit different ( " Time per period = x")
x stays now 2.5 <= x <= 3.5, before it Jumps to >10 if the tone stops.
 
The "playback drain error (DMA or IRQ trouble?)" message in /var/log/messages
is away.

Every thing else is as before.
 
"nrpacks=1" was set (hidden in /etc/modprobe.conf) from my first tests, but
unsetting it doesn't change anything.

I found a different computer with an uhci, but theres no Linux installed, so at
first i have to download some recent knoppix or something else.

Maybe i can test this on saturday oder sunday.
Comment 21 Alan Stern 2006-08-18 08:47:16 UTC
Created attachment 8827 [details]
Don't stop on ISO error and early rejection of late ISO URBs

All right.  The usbmon information points pretty definitely to a hardware
problem rather than a software problem.  Only testing on a different computer
will tell us for sure.

Your last test confirmed that the patch works as desired.  Like I expected, it
didn't solve the problem.  Here's an updated version of that patch.  It won't
solve the problem either, but it may change the symptoms a little.  Again,
please send just the usbmon log for this test.
Comment 22 Felix Schueller 2006-08-19 13:34:58 UTC
Created attachment 8836 [details]
/sys/kernel/debug/usbmon/1t 3. version (bzip2)

As you said, the patch didn't solve the problem, only one little change:

If i put load on the machine, and if the tone stops, the " Time per period = x"

message of speacker-test decreases to x ~ 0.5
Comment 23 Alan Stern 2006-08-19 14:49:12 UTC
Okay, thanks for trying it out.  Although the visible symptoms didn't change
much, there's a significant difference in the usbmon output.  It confirms that
the patch works as desired.

At this point there's nothing left for me to do but wait until you can try the
device on the other computer.

You know, it's possible that this isn't exactly a hardware issue in the USB
controller.  It could be there's something funny about the chipset on the
motherboard and it's not getting set right by the kernel.  However that would be
outside my area of expertise.
Comment 24 Felix Schueller 2006-08-20 13:45:12 UTC
It really looks like a hardware problem, I tested the speaker on an other
Computer with an uhci, and I couldn't trigger the bug.

And also a quick test (just copying a bunch of files) with an external harddisk
attached to usb on my computer gave something: [see logs below]

Is it possible that the usb_storage driver also triggers the problem, but finds
a way to recover?

And one question: If it's a hardwareproblem, why does it only occurs if I put
load an the machine? (at least if the speaker are the only devices at the bus?)

/var/log/messages:

Aug 20 21:45:41 frodo kernel: usb 1-2: reset full speed USB device using
uhci_hcd and address 2
Aug 20 21:46:59 frodo kernel: usb 1-2: reset full speed USB device using
uhci_hcd and address 2
Aug 20 21:48:37 frodo last message repeated 3 times
Aug 20 21:50:22 frodo last message repeated 2 times
Aug 20 21:51:56 frodo last message repeated 2 times
Aug 20 21:53:25 frodo kernel: usb 1-2: reset full speed USB device using
uhci_hcd and address 2
Aug 20 21:53:50 frodo kernel: usb 1-2: reset full speed USB device using
uhci_hcd and address 2
Aug 20 21:58:36 frodo kernel: usb 1-2: USB disconnect, address 2

/var/log/debug:

Aug 20 21:45:41 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:45:41 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 20 21:45:41 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:45:41 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:46:59 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:46:59 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:46:59 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:47:25 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:47:26 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:47:26 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:47:33 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:47:34 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 20 21:47:34 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:47:34 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:48:37 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:48:38 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:48:38 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:49:34 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:49:35 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:49:35 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:50:21 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:50:22 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:50:22 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:51:02 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:51:02 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 20 21:51:03 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:51:03 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:51:56 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:51:56 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:51:56 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:53:24 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:53:25 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:53:25 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:53:50 frodo kernel: usb 1-2: uhci_result_common: failed with status 440000
Aug 20 21:53:50 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:53:50 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:58:36 frodo kernel: hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0004
Aug 20 21:58:36 frodo kernel: uhci_hcd 0000:00:07.2: port 2 portsc 008a,00
Aug 20 21:58:36 frodo kernel: hub 1-0:1.0: port 2, status 0100, change 0003, 12 Mb/s
Aug 20 21:58:36 frodo kernel: usb 1-2: usb_disable_device nuking all URBs
Aug 20 21:58:36 frodo kernel: usb 1-2: unregistering interface 1-2:1.0
Aug 20 21:58:36 frodo kernel:  usbdev1.2_ep01: ep_device_release called for
usbdev1.2_ep01
Aug 20 21:58:36 frodo kernel:  usbdev1.2_ep82: ep_device_release called for
usbdev1.2_ep82
Aug 20 21:58:36 frodo kernel: usb 1-2:1.0: uevent
Aug 20 21:58:36 frodo kernel: usb 1-2: unregistering device
Aug 20 21:58:36 frodo kernel:  usbdev1.2_ep00: ep_device_release called for
usbdev1.2_ep00
Aug 20 21:58:36 frodo kernel: usb 1-2: uevent
Aug 20 21:58:36 frodo kernel: hub 1-0:1.0: debounce: port 2: total 100ms stable
100ms status 0x100
Aug 20 21:58:37 frodo kernel: usb usb1: suspend_rh (auto-stop)
Comment 25 Alan Stern 2006-08-20 14:05:45 UTC
> Is it possible that the usb_storage driver also triggers the problem, but
> finds a way to recover?

Yes, it is quite possible.  usb-storage has very good error recovery -- although
it's aimed more at recovering from errors in the attached device than errors in
the USB controller.  Notice all the reset messages in your log; each one is an
attempt to recover from an error.

> And one question: If it's a hardwareproblem, why does it only occurs if I put
> load an the machine? (at least if the speaker are the only devices at the
> bus?)

I don't know the answer.  Perhaps some component on your computer (like the UHCI
controller) is slightly defective and is operating near its limit, and
increasing the load pushes it over the edge.

Anyway, it looks like you can close out this bug report.  If anything changes,
you can re-open it.
Comment 26 Felix Schueller 2006-08-22 13:44:33 UTC
Yes, I think its time to do so (And for me to buy an Usb hostcontroller :( )

Thanks for your help.
Comment 27 Greg Kroah-Hartman 2006-08-30 01:11:43 UTC
Thanks Alan for your help on this.

Note You need to log in before you can comment on or make changes to this bug.