Bug 13700 - usb error flood in dmesg, makes kde use plenty of cpu - bisected
Summary: usb error flood in dmesg, makes kde use plenty of cpu - bisected
Status: CLOSED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: Daniel Mack
URL:
Keywords:
Depends on:
Blocks: 13070
  Show dependency tree
 
Reported: 2009-07-03 21:13 UTC by jouni susiluoto
Modified: 2009-07-27 22:22 UTC (History)
4 users (show)

See Also:
Kernel Version: 2.6.30-rc1 and later
Subsystem:
Regression: Yes
Bisected commit-id:


Attachments
lsusb -v from nonworking system (12.62 KB, text/plain)
2009-07-03 21:13 UTC, jouni susiluoto
Details
lsusb -v from 2.6.29.5 (11.74 KB, text/plain)
2009-07-03 21:16 UTC, jouni susiluoto
Details
.config of 2.6.30.1 kernel that does not work (50.11 KB, application/octet-stream)
2009-07-03 21:20 UTC, jouni susiluoto
Details
usbmon output with a good kernel (19.07 KB, text/plain)
2009-07-09 08:52 UTC, jouni susiluoto
Details
usbmon output with a bad kernel (86.96 KB, text/plain)
2009-07-09 08:53 UTC, jouni susiluoto
Details

Description jouni susiluoto 2009-07-03 21:13:31 UTC
Created attachment 22197 [details]
lsusb -v from nonworking system

With all kernels after (copied from git-bisect...)


54530bded6ecf22d683423b66fc3cd6dddb249aa is first bad commit
commit 54530bded6ecf22d683423b66fc3cd6dddb249aa
Author: Takashi Iwai <tiwai@suse.de>
Date:   Thu Feb 5 15:55:18 2009 +0100

    ALSA: usb - Add missing KERN_* prefix to printk

    Signed-off-by: Takashi Iwai <tiwai@suse.de>

:040000 040000 c9808b346d4581fd1c6df76a7a00ad29853a6250 5ab0b206b85c5b54c6a5809b4d14c1a86778442b M      sound


I get the following errors in dmesg:


[ 9009.206070] usb 5-2: new low speed USB device using uhci_hcd and address 101
[ 9009.365159] usb 5-2: string descriptor 0 read error: -32
[ 9009.387159] usb 5-2: New USB device found, idVendor=043e, idProduct=9802
[ 9009.387167] usb 5-2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 9009.387314] usb 5-2: configuration #1 chosen from 1 choice
[ 9009.395821] usb 5-2: can't set config #1, error -71
[ 9009.395931] usb 5-2: USB disconnect, address 101
[ 9009.956068] usb 5-2: new low speed USB device using uhci_hcd and address 102
[ 9010.115158] usb 5-2: string descriptor 0 read error: -32
[ 9010.134159] usb 5-2: New USB device found, idVendor=043e, idProduct=9802
[ 9010.134166] usb 5-2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 9010.134322] usb 5-2: configuration #1 chosen from 1 choice
[ 9010.138154] usb 5-2: can't set config #1, error -71
[ 9010.138273] usb 5-2: USB disconnect, address 102


With a working kernel, like 2.6.29.5, the the usb section 5-2 reads:

                                        
[    6.878042] usb 5-2: new low speed USB device using uhci_hcd and address 2
[    7.037499] usb 5-2: string descriptor 0 read error: -32 
[    7.037546] usb 5-2: New USB device found, idVendor=043e, idProduct=9802     
[    7.037549] usb 5-2: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[    7.040584] usb 5-2: configuration #1 chosen from 1 choice

lsusb for 2.6.29.5 is:


Bus 005 Device 002: ID 043e:9802 LG Electronics USA, Inc.
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

and for later kernels, it is the same, but the first line is completely missing.

Attached are lsusb -v from both nonworking and working systems, and .config of the latest tested nonworking kernel version, 2.6.31-rc1-git3.
Comment 1 jouni susiluoto 2009-07-03 21:16:47 UTC
Created attachment 22201 [details]
lsusb -v from 2.6.29.5
Comment 2 jouni susiluoto 2009-07-03 21:20:10 UTC
Created attachment 22203 [details]
.config of 2.6.30.1 kernel that does not work

Tested also with 2.6.31-rc1-git3, that does not work either.
Comment 3 Andrew Morton 2009-07-03 21:33:29 UTC
(switched to email.  Please respond via emailed reply-to-all, not via the
bugzilla web interface).

It's a post-2.6.30 regression.

On Fri, 3 Jul 2009 21:13:32 GMT bugzilla-daemon@bugzilla.kernel.org wrote:

> http://bugzilla.kernel.org/show_bug.cgi?id=13700
> 
>            Summary: usb error flood in dmesg, makes kde use plenty of cpu
>                     - bisected
>            Product: Drivers
>            Version: 2.5
>     Kernel Version: 2.6.30-rc1 and later
>           Platform: All
>         OS/Version: Linux
>               Tree: Mainline
>             Status: NEW
>           Severity: normal
>           Priority: P1
>          Component: USB
>         AssignedTo: greg@kroah.com
>         ReportedBy: jouni.susiluoto@helsinki.fi
>         Regression: Yes
> 
> 
> Created an attachment (id=22197)
>  --> (http://bugzilla.kernel.org/attachment.cgi?id=22197)
> lsusb -v from nonworking system
> 
> With all kernels after (copied from git-bisect...)
> 
> 
> 54530bded6ecf22d683423b66fc3cd6dddb249aa is first bad commit
> commit 54530bded6ecf22d683423b66fc3cd6dddb249aa
> Author: Takashi Iwai <tiwai@suse.de>
> Date:   Thu Feb 5 15:55:18 2009 +0100
> 
>     ALSA: usb - Add missing KERN_* prefix to printk
> 
>     Signed-off-by: Takashi Iwai <tiwai@suse.de>
> 
> :040000 040000 c9808b346d4581fd1c6df76a7a00ad29853a6250
> 5ab0b206b85c5b54c6a5809b4d14c1a86778442b M      sound

I think the bisect went wrong :(  That patch doesn't really do anything.

> 
> I get the following errors in dmesg:
> 
> 
> [ 9009.206070] usb 5-2: new low speed USB device using uhci_hcd and address
> 101
> [ 9009.365159] usb 5-2: string descriptor 0 read error: -32
> [ 9009.387159] usb 5-2: New USB device found, idVendor=043e, idProduct=9802
> [ 9009.387167] usb 5-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [ 9009.387314] usb 5-2: configuration #1 chosen from 1 choice
> [ 9009.395821] usb 5-2: can't set config #1, error -71
> [ 9009.395931] usb 5-2: USB disconnect, address 101
> [ 9009.956068] usb 5-2: new low speed USB device using uhci_hcd and address
> 102
> [ 9010.115158] usb 5-2: string descriptor 0 read error: -32
> [ 9010.134159] usb 5-2: New USB device found, idVendor=043e, idProduct=9802
> [ 9010.134166] usb 5-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [ 9010.134322] usb 5-2: configuration #1 chosen from 1 choice
> [ 9010.138154] usb 5-2: can't set config #1, error -71
> [ 9010.138273] usb 5-2: USB disconnect, address 102
> 
> 
> With a working kernel, like 2.6.29.5, the the usb section 5-2 reads:
> 
> 
> [    6.878042] usb 5-2: new low speed USB device using uhci_hcd and address 2
> [    7.037499] usb 5-2: string descriptor 0 read error: -32 
> [    7.037546] usb 5-2: New USB device found, idVendor=043e, idProduct=9802   
> [    7.037549] usb 5-2: New USB device strings: Mfr=0, Product=1,
> SerialNumber=0
> [    7.040584] usb 5-2: configuration #1 chosen from 1 choice
> 
> lsusb for 2.6.29.5 is:
> 
> 
> Bus 005 Device 002: ID 043e:9802 LG Electronics USA, Inc.
> Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
> Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> 
> and for later kernels, it is the same, but the first line is completely
> missing.
> 
> Attached are lsusb -v from both nonworking and working systems, and .config
> of
> the latest tested nonworking kernel version, 2.6.31-rc1-git3.
Comment 4 Takashi Iwai 2009-07-03 21:45:13 UTC
At Fri, 3 Jul 2009 14:33:25 -0700,
Andrew Morton wrote:
> 
> > 
> > With all kernels after (copied from git-bisect...)
> > 
> > 
> > 54530bded6ecf22d683423b66fc3cd6dddb249aa is first bad commit
> > commit 54530bded6ecf22d683423b66fc3cd6dddb249aa
> > Author: Takashi Iwai <tiwai@suse.de>
> > Date:   Thu Feb 5 15:55:18 2009 +0100
> > 
> >     ALSA: usb - Add missing KERN_* prefix to printk
> > 
> >     Signed-off-by: Takashi Iwai <tiwai@suse.de>
> > 
> > :040000 040000 c9808b346d4581fd1c6df76a7a00ad29853a6250
> > 5ab0b206b85c5b54c6a5809b4d14c1a86778442b M      sound
> 
> I think the bisect went wrong :(  That patch doesn't really do anything.

Indeed.

Looking at the kernel messages, it seems relevant only with the usb stack.
Maybe bisecting with limited path (drivers/usb) would be easier.


Takashi
Comment 5 jouni susiluoto 2009-07-04 10:56:34 UTC
Yes, you are right, the bisection was all wrong. The multiple choice questions good/bad are tricky...

Bisected it again, and double tested it, and the offending commit actually seems to be:

b7af0bb26899bb47ae16fb41d2296111b0784a56 is first bad commit
commit b7af0bb26899bb47ae16fb41d2296111b0784a56
Author: Daniel Mack <daniel@caiaq.de>
Date:   Fri Mar 20 19:58:57 2009 +0100

    USB: allow malformed LANGID descriptors

    When an USB hardware does not provide a valid LANGID, fall back to value
    zero which is still a reasonable default for most devices.

    Signed-off-by: Daniel Mack <daniel@caiaq.de>
    Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>

:040000 040000 4c5cd78df7c00d0242d37b7bc02ccf2aac725f43 b1d3f7826fe098fff77f06260e8ba9aa297ba514 M      drivers


The kernel at the previous commit 4c24b6d045a9d355c95ca4e6beb10ce2fd263390 does work fine with identical .config.

I hope I got it right this time. If you need any additional info, just let me know.
Comment 6 jouni susiluoto 2009-07-04 16:25:02 UTC
Apparently it was the culprit - doing

git revert b7af0bb26899bb47ae16fb41d2296111b0784a56

with the current mainline git tree solves the problem.


Jouni
Comment 7 Alan Stern 2009-07-05 15:22:50 UTC
Use usbmon to capture the USB messages when the device is first plugged in.  (See Documentation/usb/usbmon.txt for instructions.)  In fact, do it twice: once with the vanilla kernel and once with the offending patch reverted.  Attach the logs to this bug report and I'll look at them.
Comment 8 jouni susiluoto 2009-07-05 22:18:25 UTC
well, lsusb shows

 $ lsusb
Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 005 Device 002: ID 043e:9802 LG Electronics USA, Inc.
Bus 005 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub


even when there are no usb devices plugged into the usb ports at all (this is an LG LW75 laptop). This is the case with the kernels, that don't have the patch b7af0bb26899bb47ae16fb41d2296111b0784a56 (ie. the evil patch) applied.

With the broken kernels, the errorflood is there also with no devices plugged in at all, and there is no trace of the LG Electronics USA, Inc. device in lsusb

This laptop has 4 usb ports.

I'll be away until next wednesday, so before that I'll not be able to help more.


Jouni
Comment 9 Alan Stern 2009-07-06 02:26:04 UTC
The LG Electronics device must be built into the laptop.  Since you can't unplug it, you'll have to do this instead:  rmmod ehci-hcd, then rmmod uhci-hcd.  Then start usbmon, copying the 0u file.  Then modprobe uhci-hcd.  The final result will be good enough for our purposes.
Comment 10 jouni susiluoto 2009-07-09 08:52:47 UTC
Created attachment 22288 [details]
usbmon output with a good kernel
Comment 11 jouni susiluoto 2009-07-09 08:53:50 UTC
Created attachment 22289 [details]
usbmon output with a bad kernel
Comment 12 Daniel Mack 2009-07-26 23:23:21 UTC
Fix with commit to mainline 0cce2ed
Comment 13 Ozan Caglayan 2009-07-27 05:25:33 UTC
With the very same laptop, it was also an issue for 2.6.30.2. The bug is listed in the regression list reported from 2.6.30 but should be in the 2.6.29->2.6.30 one.

Anyway, that would be nice to send the patch to stable@kernel for inclusion in the next 2.6.30 release.

Thanks,
Comment 14 Ozan Caglayan 2009-07-27 05:30:40 UTC
Okay that was already CC'ed, ignore the previous one.
Comment 15 Rafael J. Wysocki 2009-07-27 22:21:40 UTC
On Monday 27 July 2009, Ozan Çağlayan wrote:
> Rafael J. Wysocki wrote On 26-07-2009 23:28:
> > This message has been generated automatically as a part of a report
> > of recent regressions.
> >
> > The following bug entry is on the current list of known regressions
> > from 2.6.30.  Please verify if it still should be listed and let me know
> > (either way).
> >
> >
> > Bug-Entry   : http://bugzilla.kernel.org/show_bug.cgi?id=13700
> > Subject             : usb error flood in dmesg, makes kde use plenty of cpu
> - bisected
> > Submitter   : jouni susiluoto <jouni.susiluoto@helsinki.fi>
> > Date                : 2009-07-03 21:13 (24 days old)
> >   
> This is also an issue for 2.6.30 so it should have been listed in the
> other 2.6.29->2.6.30 list I think.

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