pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Hi,

I wonder if this is the write place to post this issue to, but I have a
proplem when trying go suspend or hibernate my system. after enabling
pm_trace by:

echo 1 > /sys/power/pm_trace

and then issuing pm-suspend, I get the following in dmesg:

[  685.833275] PM: Entering mem sleep
[  685.833292] Suspending console(s) (use no_console_suspend to debug)
[  685.993399] pm_op(): usb_dev_suspend+0x0/0x10 returns -2
[  685.993404] PM: Device usb2 failed to suspend: error -2
[  685.993408] PM: Some devices failed to suspend
[  685.997009] PM: resume devices took 0.000 seconds
[  685.997169] PM: Finishing wakeup.

this is on 2.6.32.8, but on 2.6.33-rc8 I get the same results.

trying to find out what device this is:

$ lsusb
Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 003: ID 0bda:0159 Realtek Semiconductor Corp.
Bus 001 Device 004: ID 04f2:b16c Chicony Electronics Co., Ltd
Bus 001 Device 005: ID 03f0:231d Hewlett-Packard
Bus 001 Device 002: ID 8087:0020
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub

my persumption is that "Device usb2" would be device 002 on bus 001
above, that is, 8087:0020. googling for this USB id I found some
references here: http://forum.notebookreview.com/showthread.php?p=5906076 :

Bus 001 Device 002: ID 8087:0020 Intel Corp. Integrated Rate Matching Hub


I wonder what could be done to make this device not sabotage the suspend
process?


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Rafael J. Wysocki]

On Tuesday 23 February 2010, Ákos Maróy wrote:
> Hi,
> 
> I wonder if this is the write place to post this issue to, but I have a
> proplem when trying go suspend or hibernate my system. after enabling
> pm_trace by:
> 
> echo 1 > /sys/power/pm_trace
> 
> and then issuing pm-suspend, I get the following in dmesg:
> 
> [  685.833275] PM: Entering mem sleep
> [  685.833292] Suspending console(s) (use no_console_suspend to debug)
> [  685.993399] pm_op(): usb_dev_suspend+0x0/0x10 returns -2
> [  685.993404] PM: Device usb2 failed to suspend: error -2
> [  685.993408] PM: Some devices failed to suspend
> [  685.997009] PM: resume devices took 0.000 seconds
> [  685.997169] PM: Finishing wakeup.
> 
> this is on 2.6.32.8, but on 2.6.33-rc8 I get the same results.
> 
> trying to find out what device this is:
> 
> $ lsusb
> Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> Bus 001 Device 003: ID 0bda:0159 Realtek Semiconductor Corp.
> Bus 001 Device 004: ID 04f2:b16c Chicony Electronics Co., Ltd
> Bus 001 Device 005: ID 03f0:231d Hewlett-Packard
> Bus 001 Device 002: ID 8087:0020
> Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> 
> my persumption is that "Device usb2" would be device 002 on bus 001
> above, that is, 8087:0020. googling for this USB id I found some
> references here: http://forum.notebookreview.com/showthread.php?p=5906076 :
> 
> Bus 001 Device 002: ID 8087:0020 Intel Corp. Integrated Rate Matching Hub
> 
> 
> I wonder what could be done to make this device not sabotage the suspend
> process?

That's a good question for the USB people (CCed).

Rafael

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Tue, 23 Feb 2010, Rafael J. Wysocki wrote:

> On Tuesday 23 February 2010, Ákos Maróy wrote:
> > Hi,
> > 
> > I wonder if this is the write place to post this issue to, but I have a
> > proplem when trying go suspend or hibernate my system. after enabling
> > pm_trace by:
> > 
> > echo 1 > /sys/power/pm_trace
> > 
> > and then issuing pm-suspend, I get the following in dmesg:
> > 
> > [  685.833275] PM: Entering mem sleep
> > [  685.833292] Suspending console(s) (use no_console_suspend to debug)
> > [  685.993399] pm_op(): usb_dev_suspend+0x0/0x10 returns -2
> > [  685.993404] PM: Device usb2 failed to suspend: error -2
> > [  685.993408] PM: Some devices failed to suspend
> > [  685.997009] PM: resume devices took 0.000 seconds
> > [  685.997169] PM: Finishing wakeup.
> > 
> > this is on 2.6.32.8, but on 2.6.33-rc8 I get the same results.
> > 
> > trying to find out what device this is:
> > 
> > $ lsusb
> > Bus 002 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > Bus 001 Device 003: ID 0bda:0159 Realtek Semiconductor Corp.
> > Bus 001 Device 004: ID 04f2:b16c Chicony Electronics Co., Ltd
> > Bus 001 Device 005: ID 03f0:231d Hewlett-Packard
> > Bus 001 Device 002: ID 8087:0020
> > Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
> > 
> > my persumption is that "Device usb2" would be device 002 on bus 001
> > above, that is, 8087:0020.

It isn't.  usb2 is the root hub device on bus 2, i.e., it is device 001 
on bus 002.

> > googling for this USB id I found some
> > references here: http://forum.notebookreview.com/showthread.php?p=5906076 :
> > 
> > Bus 001 Device 002: ID 8087:0020 Intel Corp. Integrated Rate Matching Hub
> > 
> > 
> > I wonder what could be done to make this device not sabotage the suspend
> > process?

You can get more information if you enable CONFIG_USB_DEBUG in your
kernel configuration.  The most likely explanation is that the suspend
failed because one of the ports on that root hub issued a wakeup
request.

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Alan,

> You can get more information if you enable CONFIG_USB_DEBUG in your
> kernel configuration.  The most likely explanation is that the suspend
> failed because one of the ports on that root hub issued a wakeup
> request.

I tried, and this is what I seem to be getting now:


Feb 24 23:28:52 tonkachi kernel: [  348.733460] PM: Syncing filesystems ...
Feb 24 23:28:52 tonkachi kernel: [  348.903106] done.
Feb 24 23:28:52 tonkachi kernel: [  348.903123] Freezing user space
processes ... (elapsed 0.00 seconds) done.
Feb 24 23:28:52 tonkachi kernel: [  348.903808] Freezing remaining
freezable tasks ... (elapsed 0.00 seconds) done.
Feb 24 23:28:52 tonkachi kernel: [  348.903952] Suspending console(s)
(use no_console_suspend to debug)
Feb 24 23:28:52 tonkachi kernel: [  348.985903] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 24 23:28:52 tonkachi kernel: [  348.987274] PM: resume devices took
0.060 seconds
Feb 24 23:28:52 tonkachi kernel: [  348.987371] Restarting tasks ...
Feb 24 23:28:52 tonkachi kernel: [  348.988165] done.


though I don't see the pm_op() error log anymore..

would this make sense?

actually, the whole USB susbsystem seems to be very fragile - I plug in
a USB device, and the whole system freezes for about 5 seconds or more.
then the device is registered (for example, a mouse). but I unplug and
re-plug, and the device doesn't work anymore...

or I plug in an external USB DVD drive - but if I unplug it, it is still
listed in lsusb..


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Wed, 24 Feb 2010, Ákos Maróy wrote:

> Alan,
> 
> > You can get more information if you enable CONFIG_USB_DEBUG in your
> > kernel configuration.  The most likely explanation is that the suspend
> > failed because one of the ports on that root hub issued a wakeup
> > request.
> 
> I tried, and this is what I seem to be getting now:
> 
> 
> Feb 24 23:28:52 tonkachi kernel: [  348.733460] PM: Syncing filesystems ...
> Feb 24 23:28:52 tonkachi kernel: [  348.903106] done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903123] Freezing user space
> processes ... (elapsed 0.00 seconds) done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903808] Freezing remaining
> freezable tasks ... (elapsed 0.00 seconds) done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903952] Suspending console(s)
> (use no_console_suspend to debug)
> Feb 24 23:28:52 tonkachi kernel: [  348.985903] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 24 23:28:52 tonkachi kernel: [  348.987274] PM: resume devices took
> 0.060 seconds
> Feb 24 23:28:52 tonkachi kernel: [  348.987371] Restarting tasks ...
> Feb 24 23:28:52 tonkachi kernel: [  348.988165] done.
> 
> 
> though I don't see the pm_op() error log anymore..
> 
> would this make sense?

You should not be looking at the system log file; you should use the 
output from dmesg.

By the way, I noticed above that you have xhci-hcd installed.  As far 
as I know, that driver does not yet support system suspend.  You should 
try unloading xhci-hcd before doing the suspend (both with and without 
CONFIG_USB_DEBUG).

> actually, the whole USB susbsystem seems to be very fragile - I plug in
> a USB device, and the whole system freezes for about 5 seconds or more.
> then the device is registered (for example, a mouse). but I unplug and
> re-plug, and the device doesn't work anymore...
> 
> or I plug in an external USB DVD drive - but if I unplug it, it is still
> listed in lsusb..

These separate issues deserve to be investigated more closely.  The USB 
stack is not supposed to be that fragile.  Describe your environment 
more fully and provide the dmesg log from a kernel with 
CONFIG_USB_DEBUG enabled showing what happens during the experiments.

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Alan,

> You should not be looking at the system log file; you should use the 
> output from dmesg.

indeed. I'm sorry about that.

looking at dmesg, its a long line of output. points of interest look
like the following:

[   12.216797] hub 2-0:1.0: hub_suspend
[   12.216811] usb usb2: bus auto-suspend
[   12.216816] usb usb2: bus suspend fail, err -2
[   12.216820] hub 2-0:1.0: hub_resume
[   12.216864] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000
[   15.214004] hub 2-0:1.0: hub_suspend
[   15.214015] usb usb2: bus auto-suspend
[   15.214020] usb usb2: bus suspend fail, err -2
[   15.214024] hub 2-0:1.0: hub_resume
[   15.214055] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000
[   18.211195] hub 2-0:1.0: hub_suspend
[   18.211206] usb usb2: bus auto-suspend
[   18.211211] usb usb2: bus suspend fail, err -2
[   18.211215] hub 2-0:1.0: hub_resume
[   18.211254] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000
[   21.208379] hub 2-0:1.0: hub_suspend
[   21.208389] usb usb2: bus auto-suspend
[   21.208394] usb usb2: bus suspend fail, err -2
[   21.208398] hub 2-0:1.0: hub_resume
[   21.208432] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000
[   24.205564] hub 2-0:1.0: hub_suspend
[   24.205578] usb usb2: bus auto-suspend
[   24.205583] usb usb2: bus suspend fail, err -2
[   24.205587] hub 2-0:1.0: hub_resume
[   24.205624] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000

...

[   27.202742] hub 2-0:1.0: hub_suspend
[   27.202755] usb usb2: bus auto-suspend
[   27.202760] usb usb2: bus suspend fail, err -2
[   27.202764] hub 2-0:1.0: hub_resume
[   27.202807] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000
[   29.851255] usb usb2: uevent
[   29.851420] usb 2-0:1.0: uevent

...

[   30.209824] usb usb2: bus auto-suspend
[   30.209828] usb usb2: bus suspend fail, err -2
[   30.209833] hub 2-0:1.0: hub_resume
[   30.209881] hub 2-0:1.0: state 7 ports 4 chg 0000 evt 0000

and a lot of the same, repeated all over. and then:

[  407.210004] PM: Entering mem sleep
[  407.210022] Suspending console(s) (use no_console_suspend to debug)
[  407.368716] hub 2-0:1.0: hub_suspend
[  407.368726] usb usb2: bus suspend
[  407.368731] usb usb2: bus suspend fail, err -2
[  407.368734] hub 2-0:1.0: hub_resume
[  407.368768] pm_op(): usb_dev_suspend+0x0/0x10 returns -2
[  407.368773] PM: Device usb2 failed to suspend: error -2
[  407.368776] PM: Some devices failed to suspend
[  407.371952] PM: resume devices took 0.000 seconds
[  407.372122] PM: Finishing wakeup.


> By the way, I noticed above that you have xhci-hcd installed.  As far 
> as I know, that driver does not yet support system suspend.  You should 
> try unloading xhci-hcd before doing the suspend (both with and without 
> CONFIG_USB_DEBUG).

wow, rmmod xhci - and the suspend goes through fine!

what is this xhci thing anyway?

> These separate issues deserve to be investigated more closely.  The USB 
> stack is not supposed to be that fragile.  Describe your environment 
> more fully and provide the dmesg log from a kernel with 
> CONFIG_USB_DEBUG enabled showing what happens during the experiments.

indeed. interestingly, xhci may be the culprit, as without xhci, the
external DVD doesn't even register at all.

loadind xhci, I get:

Feb 25 17:33:50 tonkachi kernel: [  168.203418] xhci_hcd 0000:02:00.0:
PCI INT A -> GSI 16 (level, low) -> IRQ 16
Feb 25 17:33:50 tonkachi kernel: [  168.203568] xhci_hcd 0000:02:00.0:
xHCI Host Controller
Feb 25 17:33:50 tonkachi kernel: [  168.203689] xhci_hcd 0000:02:00.0:
new USB bus registered, assigned bus number 2
Feb 25 17:33:50 tonkachi kernel: [  168.203832] xhci_hcd 0000:02:00.0:
irq 16, io mem 0xd4000000
Feb 25 17:33:50 tonkachi kernel: [  168.203875] usb usb2: config 1
interface 0 altsetting 0 endpoint 0x81 has no SuperSpeed companion
descriptor
Feb 25 17:33:50 tonkachi kernel: [  168.203912] usb usb2: New USB device
found, idVendor=1d6b, idProduct=0002
Feb 25 17:33:50 tonkachi kernel: [  168.203919] usb usb2: New USB device
strings: Mfr=3, Product=2, SerialNumber=1
Feb 25 17:33:50 tonkachi kernel: [  168.203925] usb usb2: Product: xHCI
Host Controller
Feb 25 17:33:50 tonkachi kernel: [  168.203931] usb usb2: Manufacturer:
Linux 2.6.32.8-usb-debug xhci_hcd
Feb 25 17:33:50 tonkachi kernel: [  168.203937] usb usb2: SerialNumber:
0000:02:00.0
Feb 25 17:33:50 tonkachi kernel: [  168.204089] usb usb2: configuration
#1 chosen from 1 choice
Feb 25 17:33:50 tonkachi kernel: [  168.204198] hub 2-0:1.0: USB hub found
Feb 25 17:33:50 tonkachi kernel: [  168.204213] hub 2-0:1.0: 4 ports
detected


plugging in the USB DVD drive, there's a system 'freeze' for about 5
seconds (nothing is responding, not even caps lock), then I get in syslog:

Feb 25 17:34:39 tonkachi kernel: [  217.433960] Registered led device:
iwl-phy0::radio
Feb 25 17:34:39 tonkachi kernel: [  217.433990] Registered led device:
iwl-phy0::assoc
Feb 25 17:34:39 tonkachi kernel: [  217.434020] Registered led device:
iwl-phy0::RX
Feb 25 17:34:39 tonkachi kernel: [  217.434045] Registered led device:
iwl-phy0::TX
Feb 25 17:34:39 tonkachi kernel: [  217.463366] usb 2-4: new high speed
USB device using xhci_hcd and address 0
Feb 25 17:34:39 tonkachi kernel: [  217.485828] usb 2-4: New USB device
found, idVendor=058f, idProduct=6254
Feb 25 17:34:39 tonkachi kernel: [  217.485834] usb 2-4: New USB device
strings: Mfr=0, Product=0, SerialNumber=0
Feb 25 17:34:39 tonkachi kernel: [  217.485949] usb 2-4: configuration
#1 chosen from 1 choice
Feb 25 17:34:39 tonkachi kernel: [  217.485963] usb 2-4: ep 0x81 -
rounding interval to 2048 microframes
Feb 25 17:34:39 tonkachi kernel: [  217.487002] hub 2-4:1.0: USB hub found
Feb 25 17:34:39 tonkachi kernel: [  217.487502] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:39 tonkachi kernel: [  217.487533] hub 2-4:1.0: 3 ports
detected
Feb 25 17:34:40 tonkachi kernel: [  217.782947] usb 2-4.1: new high
speed USB device using xhci_hcd and address 0
Feb 25 17:34:40 tonkachi kernel: [  217.806372] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.807238] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.808106] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.808996] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.809420] usb 2-4.1: New USB
device found, idVendor=152d, idProduct=2339
Feb 25 17:34:40 tonkachi kernel: [  217.809425] usb 2-4.1: New USB
device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 17:34:40 tonkachi kernel: [  217.809430] usb 2-4.1: Product: USB
to ATA/ATAPI Bridge
Feb 25 17:34:40 tonkachi kernel: [  217.809434] usb 2-4.1: Manufacturer:
JMicron
Feb 25 17:34:40 tonkachi kernel: [  217.809437] usb 2-4.1: SerialNumber:
6A1713351FFF
Feb 25 17:34:40 tonkachi kernel: [  217.809574] usb 2-4.1: configuration
#1 chosen from 1 choice
Feb 25 17:34:40 tonkachi kernel: [  217.811213] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.812078] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:34:40 tonkachi kernel: [  217.840485] Initializing USB Mass
Storage driver...
Feb 25 17:34:40 tonkachi kernel: [  217.840664] scsi6 : SCSI emulation
for USB Mass Storage devices
Feb 25 17:34:40 tonkachi kernel: [  217.840795] usbcore: registered new
interface driver usb-storage
Feb 25 17:34:40 tonkachi kernel: [  217.840800] USB Mass Storage support
registered.
Feb 25 17:34:45 tonkachi kernel: [  222.833493] scsi 6:0:0:0: CD-ROM
        hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
Feb 25 17:34:45 tonkachi kernel: [  222.846361] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:34:45 tonkachi kernel: [  222.847589] sr0: scsi3-mmc drive:
24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
Feb 25 17:34:45 tonkachi kernel: [  222.847597] Uniform CD-ROM driver
Revision: 3.20
Feb 25 17:34:45 tonkachi kernel: [  222.849281] sr 6:0:0:0: Attached
scsi generic sg2 type 5
Feb 25 17:34:45 tonkachi kernel: [  222.958589] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint


now, I unplug the USB DVD drive:

Feb 25 17:35:38 tonkachi kernel: [  276.374282] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 17:35:39 tonkachi kernel: [  276.728151] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 17:35:39 tonkachi kernel: [  276.728819] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint


I plug it back in, with a DVD in the drive:

Feb 25 17:41:21 tonkachi kernel: [  618.701586] Registered led device:
iwl-phy0::radio
Feb 25 17:41:21 tonkachi kernel: [  618.701619] Registered led device:
iwl-phy0::assoc
Feb 25 17:41:21 tonkachi kernel: [  618.701649] Registered led device:
iwl-phy0::RX
Feb 25 17:41:21 tonkachi kernel: [  618.701674] Registered led device:
iwl-phy0::TX
Feb 25 17:41:21 tonkachi kernel: [  618.719536] usb 2-3: new high speed
USB device using xhci_hcd and address 0
Feb 25 17:41:21 tonkachi kernel: [  618.742028] usb 2-3: New USB device
found, idVendor=058f, idProduct=6254
Feb 25 17:41:21 tonkachi kernel: [  618.742034] usb 2-3: New USB device
strings: Mfr=0, Product=0, SerialNumber=0
Feb 25 17:41:21 tonkachi kernel: [  618.742155] usb 2-3: configuration
#1 chosen from 1 choice
Feb 25 17:41:21 tonkachi kernel: [  618.742168] usb 2-3: ep 0x81 -
rounding interval to 2048 microframes
Feb 25 17:41:21 tonkachi kernel: [  618.743316] hub 2-3:1.0: USB hub found
Feb 25 17:41:21 tonkachi kernel: [  618.743794] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  618.743830] hub 2-3:1.0: 3 ports
detected
Feb 25 17:41:21 tonkachi kernel: [  619.045944] usb 2-3.1: new high
speed USB device using xhci_hcd and address 0
Feb 25 17:41:21 tonkachi kernel: [  619.069424] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.070295] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.071173] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.072042] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.072398] usb 2-3.1: New USB
device found, idVendor=152d, idProduct=2339
Feb 25 17:41:21 tonkachi kernel: [  619.072404] usb 2-3.1: New USB
device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 17:41:21 tonkachi kernel: [  619.072408] usb 2-3.1: Product: USB
to ATA/ATAPI Bridge
Feb 25 17:41:21 tonkachi kernel: [  619.072412] usb 2-3.1: Manufacturer:
JMicron
Feb 25 17:41:21 tonkachi kernel: [  619.072416] usb 2-3.1: SerialNumber:
6A1713351FFF
Feb 25 17:41:21 tonkachi kernel: [  619.072530] usb 2-3.1: configuration
#1 chosen from 1 choice
Feb 25 17:41:21 tonkachi kernel: [  619.074124] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.074999] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 17:41:21 tonkachi kernel: [  619.075559] scsi7 : SCSI emulation
for USB Mass Storage devices



Feb 25 17:41:26 tonkachi kernel: [  624.073472] scsi 7:0:0:0: CD-ROM
        hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
Feb 25 17:41:26 tonkachi kernel: [  624.086041] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:41:26 tonkachi kernel: [  624.087393] sr0: scsi3-mmc drive:
62x/62x writer dvd-ram cd/rw xa/form2 cdda tray
Feb 25 17:41:26 tonkachi kernel: [  624.088377] sr 7:0:0:0: Attached
scsi generic sg2 type 5
Feb 25 17:41:26 tonkachi kernel: [  624.118679] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:41:29 tonkachi kernel: [  626.883451] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:41:29 tonkachi kernel: [  626.915739] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:41:29 tonkachi kernel: [  627.147000] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 17:41:29 tonkachi kernel: [  627.270741] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint


unplug:

Feb 25 17:42:05 tonkachi kernel: [  663.327552] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 17:42:06 tonkachi kernel: [  663.364546] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 17:42:06 tonkachi kernel: [  663.365228] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 17:42:10 tonkachi kernel: [  667.360714] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.360956] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.361101] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.362264] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.363730] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.377669] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.377910] VFS: busy inodes on
changed media or resized disk sr0
Feb 25 17:42:10 tonkachi kernel: [  667.378158] VFS: busy inodes on
changed media or resized disk sr0



plug back in:

Feb 25 17:42:50 tonkachi kernel: [  707.759089] Registered led device:
iwl-phy0::radio
Feb 25 17:42:50 tonkachi kernel: [  707.759179] Registered led device:
iwl-phy0::assoc
Feb 25 17:42:50 tonkachi kernel: [  707.759412] Registered led device:
iwl-phy0::RX
Feb 25 17:42:50 tonkachi kernel: [  707.759572] Registered led device:
iwl-phy0::TX



but the disk does not register anymore :(


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Alan,

> By the way, I noticed above that you have xhci-hcd installed.  As far 
> as I know, that driver does not yet support system suspend.  You should 
> try unloading xhci-hcd before doing the suspend (both with and without 
> CONFIG_USB_DEBUG).

as I added xhci among the SUSPEND_MODULES for pm, I tried pm-hibernate
after a successful pm-suspend. but this doesn't work, the machine just
goes blank, and it doesn't power off. doing a power cycle boots it 'as
usual'.

how can one debug the hibernation process?


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Thu, 25 Feb 2010, Ákos Maróy wrote:

> > By the way, I noticed above that you have xhci-hcd installed.  As far 
> > as I know, that driver does not yet support system suspend.  You should 
> > try unloading xhci-hcd before doing the suspend (both with and without 
> > CONFIG_USB_DEBUG).
> 
> wow, rmmod xhci - and the suspend goes through fine!
> 
> what is this xhci thing anyway?

It is the driver for USB-3.0 controllers.  It's relatively new and not 
as mature as the USB-2.0 drivers.

I'm a little surprised that it is running on your system.  Why would 
you have USB-3.0 hardware?

> > These separate issues deserve to be investigated more closely.  The USB 
> > stack is not supposed to be that fragile.  Describe your environment 
> > more fully and provide the dmesg log from a kernel with 
> > CONFIG_USB_DEBUG enabled showing what happens during the experiments.
> 
> indeed. interestingly, xhci may be the culprit, as without xhci, the
> external DVD doesn't even register at all.
> 
> loadind xhci, I get:
> 
> Feb 25 17:33:50 tonkachi kernel: [  168.203418] xhci_hcd 0000:02:00.0:
> PCI INT A -> GSI 16 (level, low) -> IRQ 16
> Feb 25 17:33:50 tonkachi kernel: [  168.203568] xhci_hcd 0000:02:00.0:
> xHCI Host Controller
> Feb 25 17:33:50 tonkachi kernel: [  168.203689] xhci_hcd 0000:02:00.0:
> new USB bus registered, assigned bus number 2
> Feb 25 17:33:50 tonkachi kernel: [  168.203832] xhci_hcd 0000:02:00.0:
> irq 16, io mem 0xd4000000
> Feb 25 17:33:50 tonkachi kernel: [  168.203875] usb usb2: config 1
> interface 0 altsetting 0 endpoint 0x81 has no SuperSpeed companion
> descriptor
> Feb 25 17:33:50 tonkachi kernel: [  168.203912] usb usb2: New USB device
> found, idVendor=1d6b, idProduct=0002
> Feb 25 17:33:50 tonkachi kernel: [  168.203919] usb usb2: New USB device
> strings: Mfr=3, Product=2, SerialNumber=1
> Feb 25 17:33:50 tonkachi kernel: [  168.203925] usb usb2: Product: xHCI
> Host Controller
> Feb 25 17:33:50 tonkachi kernel: [  168.203931] usb usb2: Manufacturer:
> Linux 2.6.32.8-usb-debug xhci_hcd
> Feb 25 17:33:50 tonkachi kernel: [  168.203937] usb usb2: SerialNumber:
> 0000:02:00.0
> Feb 25 17:33:50 tonkachi kernel: [  168.204089] usb usb2: configuration
> #1 chosen from 1 choice
> Feb 25 17:33:50 tonkachi kernel: [  168.204198] hub 2-0:1.0: USB hub found
> Feb 25 17:33:50 tonkachi kernel: [  168.204213] hub 2-0:1.0: 4 ports
> detected
> 
> 
> plugging in the USB DVD drive, there's a system 'freeze' for about 5
> seconds (nothing is responding, not even caps lock), then I get in syslog:
> 
> Feb 25 17:34:39 tonkachi kernel: [  217.433960] Registered led device:
> iwl-phy0::radio
> Feb 25 17:34:39 tonkachi kernel: [  217.433990] Registered led device:
> iwl-phy0::assoc
> Feb 25 17:34:39 tonkachi kernel: [  217.434020] Registered led device:
> iwl-phy0::RX
> Feb 25 17:34:39 tonkachi kernel: [  217.434045] Registered led device:
> iwl-phy0::TX
> Feb 25 17:34:39 tonkachi kernel: [  217.463366] usb 2-4: new high speed
> USB device using xhci_hcd and address 0
> Feb 25 17:34:39 tonkachi kernel: [  217.485828] usb 2-4: New USB device
> found, idVendor=058f, idProduct=6254
> Feb 25 17:34:39 tonkachi kernel: [  217.485834] usb 2-4: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Feb 25 17:34:39 tonkachi kernel: [  217.485949] usb 2-4: configuration
> #1 chosen from 1 choice
> Feb 25 17:34:39 tonkachi kernel: [  217.485963] usb 2-4: ep 0x81 -
> rounding interval to 2048 microframes
> Feb 25 17:34:39 tonkachi kernel: [  217.487002] hub 2-4:1.0: USB hub found
> Feb 25 17:34:39 tonkachi kernel: [  217.487502] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:39 tonkachi kernel: [  217.487533] hub 2-4:1.0: 3 ports
> detected
> Feb 25 17:34:40 tonkachi kernel: [  217.782947] usb 2-4.1: new high
> speed USB device using xhci_hcd and address 0
> Feb 25 17:34:40 tonkachi kernel: [  217.806372] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.807238] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.808106] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.808996] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.809420] usb 2-4.1: New USB
> device found, idVendor=152d, idProduct=2339
> Feb 25 17:34:40 tonkachi kernel: [  217.809425] usb 2-4.1: New USB
> device strings: Mfr=1, Product=2, SerialNumber=5
> Feb 25 17:34:40 tonkachi kernel: [  217.809430] usb 2-4.1: Product: USB
> to ATA/ATAPI Bridge
> Feb 25 17:34:40 tonkachi kernel: [  217.809434] usb 2-4.1: Manufacturer:
> JMicron
> Feb 25 17:34:40 tonkachi kernel: [  217.809437] usb 2-4.1: SerialNumber:
> 6A1713351FFF
> Feb 25 17:34:40 tonkachi kernel: [  217.809574] usb 2-4.1: configuration
> #1 chosen from 1 choice
> Feb 25 17:34:40 tonkachi kernel: [  217.811213] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.812078] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:34:40 tonkachi kernel: [  217.840485] Initializing USB Mass
> Storage driver...
> Feb 25 17:34:40 tonkachi kernel: [  217.840664] scsi6 : SCSI emulation
> for USB Mass Storage devices
> Feb 25 17:34:40 tonkachi kernel: [  217.840795] usbcore: registered new
> interface driver usb-storage
> Feb 25 17:34:40 tonkachi kernel: [  217.840800] USB Mass Storage support
> registered.
> Feb 25 17:34:45 tonkachi kernel: [  222.833493] scsi 6:0:0:0: CD-ROM
>         hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
> Feb 25 17:34:45 tonkachi kernel: [  222.846361] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:34:45 tonkachi kernel: [  222.847589] sr0: scsi3-mmc drive:
> 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
> Feb 25 17:34:45 tonkachi kernel: [  222.847597] Uniform CD-ROM driver
> Revision: 3.20
> Feb 25 17:34:45 tonkachi kernel: [  222.849281] sr 6:0:0:0: Attached
> scsi generic sg2 type 5
> Feb 25 17:34:45 tonkachi kernel: [  222.958589] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> 
> 
> now, I unplug the USB DVD drive:
> 
> Feb 25 17:35:38 tonkachi kernel: [  276.374282] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 17:35:39 tonkachi kernel: [  276.728151] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 17:35:39 tonkachi kernel: [  276.728819] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> 
> 
> I plug it back in, with a DVD in the drive:
> 
> Feb 25 17:41:21 tonkachi kernel: [  618.701586] Registered led device:
> iwl-phy0::radio
> Feb 25 17:41:21 tonkachi kernel: [  618.701619] Registered led device:
> iwl-phy0::assoc
> Feb 25 17:41:21 tonkachi kernel: [  618.701649] Registered led device:
> iwl-phy0::RX
> Feb 25 17:41:21 tonkachi kernel: [  618.701674] Registered led device:
> iwl-phy0::TX
> Feb 25 17:41:21 tonkachi kernel: [  618.719536] usb 2-3: new high speed
> USB device using xhci_hcd and address 0
> Feb 25 17:41:21 tonkachi kernel: [  618.742028] usb 2-3: New USB device
> found, idVendor=058f, idProduct=6254
> Feb 25 17:41:21 tonkachi kernel: [  618.742034] usb 2-3: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Feb 25 17:41:21 tonkachi kernel: [  618.742155] usb 2-3: configuration
> #1 chosen from 1 choice
> Feb 25 17:41:21 tonkachi kernel: [  618.742168] usb 2-3: ep 0x81 -
> rounding interval to 2048 microframes
> Feb 25 17:41:21 tonkachi kernel: [  618.743316] hub 2-3:1.0: USB hub found
> Feb 25 17:41:21 tonkachi kernel: [  618.743794] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  618.743830] hub 2-3:1.0: 3 ports
> detected
> Feb 25 17:41:21 tonkachi kernel: [  619.045944] usb 2-3.1: new high
> speed USB device using xhci_hcd and address 0
> Feb 25 17:41:21 tonkachi kernel: [  619.069424] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.070295] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.071173] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.072042] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.072398] usb 2-3.1: New USB
> device found, idVendor=152d, idProduct=2339
> Feb 25 17:41:21 tonkachi kernel: [  619.072404] usb 2-3.1: New USB
> device strings: Mfr=1, Product=2, SerialNumber=5
> Feb 25 17:41:21 tonkachi kernel: [  619.072408] usb 2-3.1: Product: USB
> to ATA/ATAPI Bridge
> Feb 25 17:41:21 tonkachi kernel: [  619.072412] usb 2-3.1: Manufacturer:
> JMicron
> Feb 25 17:41:21 tonkachi kernel: [  619.072416] usb 2-3.1: SerialNumber:
> 6A1713351FFF
> Feb 25 17:41:21 tonkachi kernel: [  619.072530] usb 2-3.1: configuration
> #1 chosen from 1 choice
> Feb 25 17:41:21 tonkachi kernel: [  619.074124] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.074999] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 17:41:21 tonkachi kernel: [  619.075559] scsi7 : SCSI emulation
> for USB Mass Storage devices
> 
> 
> 
> Feb 25 17:41:26 tonkachi kernel: [  624.073472] scsi 7:0:0:0: CD-ROM
>         hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
> Feb 25 17:41:26 tonkachi kernel: [  624.086041] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:41:26 tonkachi kernel: [  624.087393] sr0: scsi3-mmc drive:
> 62x/62x writer dvd-ram cd/rw xa/form2 cdda tray
> Feb 25 17:41:26 tonkachi kernel: [  624.088377] sr 7:0:0:0: Attached
> scsi generic sg2 type 5
> Feb 25 17:41:26 tonkachi kernel: [  624.118679] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:41:29 tonkachi kernel: [  626.883451] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:41:29 tonkachi kernel: [  626.915739] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:41:29 tonkachi kernel: [  627.147000] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> Feb 25 17:41:29 tonkachi kernel: [  627.270741] xhci_hcd 0000:02:00.0:
> WARN: Stalled endpoint
> 
> 
> unplug:
> 
> Feb 25 17:42:05 tonkachi kernel: [  663.327552] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 17:42:06 tonkachi kernel: [  663.364546] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 17:42:06 tonkachi kernel: [  663.365228] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 17:42:10 tonkachi kernel: [  667.360714] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.360956] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.361101] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.362264] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.363730] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.377669] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.377910] VFS: busy inodes on
> changed media or resized disk sr0
> Feb 25 17:42:10 tonkachi kernel: [  667.378158] VFS: busy inodes on
> changed media or resized disk sr0
> 
> 
> 
> plug back in:
> 
> Feb 25 17:42:50 tonkachi kernel: [  707.759089] Registered led device:
> iwl-phy0::radio
> Feb 25 17:42:50 tonkachi kernel: [  707.759179] Registered led device:
> iwl-phy0::assoc
> Feb 25 17:42:50 tonkachi kernel: [  707.759412] Registered led device:
> iwl-phy0::RX
> Feb 25 17:42:50 tonkachi kernel: [  707.759572] Registered led device:
> iwl-phy0::TX
> 
> 
> 
> but the disk does not register anymore :(

This is something Sarah should look into.  She's the main developer 
behind xhci-hcd.

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Sarah Sharp]

On Thu, Feb 25, 2010 at 12:46:59PM -0500, Alan Stern wrote:
> On Thu, 25 Feb 2010, Ákos Maróy wrote:
> 
> > > By the way, I noticed above that you have xhci-hcd installed.  As far 
> > > as I know, that driver does not yet support system suspend.  You should 
> > > try unloading xhci-hcd before doing the suspend (both with and without 
> > > CONFIG_USB_DEBUG).
> > 
> > wow, rmmod xhci - and the suspend goes through fine!
> > 
> > what is this xhci thing anyway?
> 
> It is the driver for USB-3.0 controllers.  It's relatively new and not 
> as mature as the USB-2.0 drivers.
> 
> I'm a little surprised that it is running on your system.  Why would 
> you have USB-3.0 hardware?

USB 3.0 hosts and devices are now available commercially.  I think the
HP envy laptop has an integrated USB 3.0 host.  Ákos, which host
controller do you have?  Is it a PCIe add-in card, a PCI express card,
or a port on a laptop?

The xHCI driver doesn't support PCI suspend, and it also doesn't support
suspending devices under the xHCI host.  The xHCI hardware needs to do
some extra work when a device is suspended, and I haven't added that API
to the USB core yet.  In short, power management sucks under xHCI. :-/

> > > These separate issues deserve to be investigated more closely.  The USB 
> > > stack is not supposed to be that fragile.  Describe your environment 
> > > more fully and provide the dmesg log from a kernel with 
> > > CONFIG_USB_DEBUG enabled showing what happens during the experiments.
> > 
> > indeed. interestingly, xhci may be the culprit, as without xhci, the
> > external DVD doesn't even register at all.
> > 
> > loadind xhci, I get:
> > 
> > Feb 25 17:33:50 tonkachi kernel: [  168.203418] xhci_hcd 0000:02:00.0:
> > PCI INT A -> GSI 16 (level, low) -> IRQ 16
> > Feb 25 17:33:50 tonkachi kernel: [  168.203568] xhci_hcd 0000:02:00.0:
> > xHCI Host Controller
> > Feb 25 17:33:50 tonkachi kernel: [  168.203689] xhci_hcd 0000:02:00.0:
> > new USB bus registered, assigned bus number 2
> > Feb 25 17:33:50 tonkachi kernel: [  168.203832] xhci_hcd 0000:02:00.0:
> > irq 16, io mem 0xd4000000
> > Feb 25 17:33:50 tonkachi kernel: [  168.203875] usb usb2: config 1
> > interface 0 altsetting 0 endpoint 0x81 has no SuperSpeed companion
> > descriptor
> > Feb 25 17:33:50 tonkachi kernel: [  168.203912] usb usb2: New USB device
> > found, idVendor=1d6b, idProduct=0002
> > Feb 25 17:33:50 tonkachi kernel: [  168.203919] usb usb2: New USB device
> > strings: Mfr=3, Product=2, SerialNumber=1
> > Feb 25 17:33:50 tonkachi kernel: [  168.203925] usb usb2: Product: xHCI
> > Host Controller
> > Feb 25 17:33:50 tonkachi kernel: [  168.203931] usb usb2: Manufacturer:
> > Linux 2.6.32.8-usb-debug xhci_hcd
> > Feb 25 17:33:50 tonkachi kernel: [  168.203937] usb usb2: SerialNumber:
> > 0000:02:00.0
> > Feb 25 17:33:50 tonkachi kernel: [  168.204089] usb usb2: configuration
> > #1 chosen from 1 choice
> > Feb 25 17:33:50 tonkachi kernel: [  168.204198] hub 2-0:1.0: USB hub found
> > Feb 25 17:33:50 tonkachi kernel: [  168.204213] hub 2-0:1.0: 4 ports
> > detected
> > 
> > 
> > plugging in the USB DVD drive, there's a system 'freeze' for about 5
> > seconds (nothing is responding, not even caps lock), then I get in syslog:

Oh, freezes are not good.  I wonder if the xHCI host is taking a long
time to respond to a hardware command?  Can you turn on
CONFIG_USB_XHCI_HCD_DEBUGGING and send me the dmesg when you plug in the
device?

> > Feb 25 17:34:39 tonkachi kernel: [  217.433960] Registered led device:
> > iwl-phy0::radio
> > Feb 25 17:34:39 tonkachi kernel: [  217.433990] Registered led device:
> > iwl-phy0::assoc
> > Feb 25 17:34:39 tonkachi kernel: [  217.434020] Registered led device:
> > iwl-phy0::RX
> > Feb 25 17:34:39 tonkachi kernel: [  217.434045] Registered led device:
> > iwl-phy0::TX
> > Feb 25 17:34:39 tonkachi kernel: [  217.463366] usb 2-4: new high speed
> > USB device using xhci_hcd and address 0
> > Feb 25 17:34:39 tonkachi kernel: [  217.485828] usb 2-4: New USB device
> > found, idVendor=058f, idProduct=6254
> > Feb 25 17:34:39 tonkachi kernel: [  217.485834] usb 2-4: New USB device
> > strings: Mfr=0, Product=0, SerialNumber=0
> > Feb 25 17:34:39 tonkachi kernel: [  217.485949] usb 2-4: configuration
> > #1 chosen from 1 choice
> > Feb 25 17:34:39 tonkachi kernel: [  217.485963] usb 2-4: ep 0x81 -
> > rounding interval to 2048 microframes
> > Feb 25 17:34:39 tonkachi kernel: [  217.487002] hub 2-4:1.0: USB hub found

Did you plug in the DVD device behind a USB hub?  Or is the hub a part
of the device?

> > Feb 25 17:34:39 tonkachi kernel: [  217.487502] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:39 tonkachi kernel: [  217.487533] hub 2-4:1.0: 3 ports
> > detected
> > Feb 25 17:34:40 tonkachi kernel: [  217.782947] usb 2-4.1: new high
> > speed USB device using xhci_hcd and address 0
> > Feb 25 17:34:40 tonkachi kernel: [  217.806372] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.807238] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.808106] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.808996] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.809420] usb 2-4.1: New USB
> > device found, idVendor=152d, idProduct=2339
> > Feb 25 17:34:40 tonkachi kernel: [  217.809425] usb 2-4.1: New USB
> > device strings: Mfr=1, Product=2, SerialNumber=5
> > Feb 25 17:34:40 tonkachi kernel: [  217.809430] usb 2-4.1: Product: USB
> > to ATA/ATAPI Bridge
> > Feb 25 17:34:40 tonkachi kernel: [  217.809434] usb 2-4.1: Manufacturer:
> > JMicron
> > Feb 25 17:34:40 tonkachi kernel: [  217.809437] usb 2-4.1: SerialNumber:
> > 6A1713351FFF
> > Feb 25 17:34:40 tonkachi kernel: [  217.809574] usb 2-4.1: configuration
> > #1 chosen from 1 choice
> > Feb 25 17:34:40 tonkachi kernel: [  217.811213] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.812078] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:34:40 tonkachi kernel: [  217.840485] Initializing USB Mass
> > Storage driver...
> > Feb 25 17:34:40 tonkachi kernel: [  217.840664] scsi6 : SCSI emulation
> > for USB Mass Storage devices
> > Feb 25 17:34:40 tonkachi kernel: [  217.840795] usbcore: registered new
> > interface driver usb-storage
> > Feb 25 17:34:40 tonkachi kernel: [  217.840800] USB Mass Storage support
> > registered.
> > Feb 25 17:34:45 tonkachi kernel: [  222.833493] scsi 6:0:0:0: CD-ROM
> >         hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
> > Feb 25 17:34:45 tonkachi kernel: [  222.846361] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:34:45 tonkachi kernel: [  222.847589] sr0: scsi3-mmc drive:
> > 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
> > Feb 25 17:34:45 tonkachi kernel: [  222.847597] Uniform CD-ROM driver
> > Revision: 3.20
> > Feb 25 17:34:45 tonkachi kernel: [  222.849281] sr 6:0:0:0: Attached
> > scsi generic sg2 type 5
> > Feb 25 17:34:45 tonkachi kernel: [  222.958589] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> >
> >
> > now, I unplug the USB DVD drive:
> > 
> > Feb 25 17:35:38 tonkachi kernel: [  276.374282] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > Feb 25 17:35:39 tonkachi kernel: [  276.728151] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > Feb 25 17:35:39 tonkachi kernel: [  276.728819] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > 
> > 
> > I plug it back in, with a DVD in the drive:
> > 
> > Feb 25 17:41:21 tonkachi kernel: [  618.701586] Registered led device:
> > iwl-phy0::radio
> > Feb 25 17:41:21 tonkachi kernel: [  618.701619] Registered led device:
> > iwl-phy0::assoc
> > Feb 25 17:41:21 tonkachi kernel: [  618.701649] Registered led device:
> > iwl-phy0::RX
> > Feb 25 17:41:21 tonkachi kernel: [  618.701674] Registered led device:
> > iwl-phy0::TX
> > Feb 25 17:41:21 tonkachi kernel: [  618.719536] usb 2-3: new high speed
> > USB device using xhci_hcd and address 0
> > Feb 25 17:41:21 tonkachi kernel: [  618.742028] usb 2-3: New USB device
> > found, idVendor=058f, idProduct=6254
> > Feb 25 17:41:21 tonkachi kernel: [  618.742034] usb 2-3: New USB device
> > strings: Mfr=0, Product=0, SerialNumber=0
> > Feb 25 17:41:21 tonkachi kernel: [  618.742155] usb 2-3: configuration
> > #1 chosen from 1 choice
> > Feb 25 17:41:21 tonkachi kernel: [  618.742168] usb 2-3: ep 0x81 -
> > rounding interval to 2048 microframes

That looks like a rather long polling interval.  Can you post the output
of `lsusb -vvv -d 058f:6254`?

> > Feb 25 17:41:21 tonkachi kernel: [  618.743316] hub 2-3:1.0: USB hub found
> > Feb 25 17:41:21 tonkachi kernel: [  618.743794] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  618.743830] hub 2-3:1.0: 3 ports
> > detected
> > Feb 25 17:41:21 tonkachi kernel: [  619.045944] usb 2-3.1: new high
> > speed USB device using xhci_hcd and address 0
> > Feb 25 17:41:21 tonkachi kernel: [  619.069424] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.070295] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.071173] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.072042] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.072398] usb 2-3.1: New USB
> > device found, idVendor=152d, idProduct=2339
> > Feb 25 17:41:21 tonkachi kernel: [  619.072404] usb 2-3.1: New USB
> > device strings: Mfr=1, Product=2, SerialNumber=5
> > Feb 25 17:41:21 tonkachi kernel: [  619.072408] usb 2-3.1: Product: USB
> > to ATA/ATAPI Bridge
> > Feb 25 17:41:21 tonkachi kernel: [  619.072412] usb 2-3.1: Manufacturer:
> > JMicron
> > Feb 25 17:41:21 tonkachi kernel: [  619.072416] usb 2-3.1: SerialNumber:
> > 6A1713351FFF
> > Feb 25 17:41:21 tonkachi kernel: [  619.072530] usb 2-3.1: configuration
> > #1 chosen from 1 choice
> > Feb 25 17:41:21 tonkachi kernel: [  619.074124] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.074999] xhci_hcd 0000:02:00.0:
> > WARN: short transfer on control ep
> > Feb 25 17:41:21 tonkachi kernel: [  619.075559] scsi7 : SCSI emulation
> > for USB Mass Storage devices
> > 
> > 
> > 
> > Feb 25 17:41:26 tonkachi kernel: [  624.073472] scsi 7:0:0:0: CD-ROM
> >         hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
> > Feb 25 17:41:26 tonkachi kernel: [  624.086041] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:41:26 tonkachi kernel: [  624.087393] sr0: scsi3-mmc drive:
> > 62x/62x writer dvd-ram cd/rw xa/form2 cdda tray
> > Feb 25 17:41:26 tonkachi kernel: [  624.088377] sr 7:0:0:0: Attached
> > scsi generic sg2 type 5
> > Feb 25 17:41:26 tonkachi kernel: [  624.118679] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:41:29 tonkachi kernel: [  626.883451] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:41:29 tonkachi kernel: [  626.915739] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:41:29 tonkachi kernel: [  627.147000] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint
> > Feb 25 17:41:29 tonkachi kernel: [  627.270741] xhci_hcd 0000:02:00.0:
> > WARN: Stalled endpoint

Can you read the DVD at this point?

> > unplug:
> > 
> > Feb 25 17:42:05 tonkachi kernel: [  663.327552] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > Feb 25 17:42:06 tonkachi kernel: [  663.364546] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > Feb 25 17:42:06 tonkachi kernel: [  663.365228] xhci_hcd 0000:02:00.0:
> > WARN: transfer error on endpoint
> > Feb 25 17:42:10 tonkachi kernel: [  667.360714] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.360956] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.361101] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.362264] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.363730] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.377669] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.377910] VFS: busy inodes on
> > changed media or resized disk sr0
> > Feb 25 17:42:10 tonkachi kernel: [  667.378158] VFS: busy inodes on
> > changed media or resized disk sr0

Did you unmount the DVD before you removed it?  I'm not sure what the
VFS errors are, but it looks like VFS doesn't like you removing the
disk.

> > plug back in:
> > 
> > Feb 25 17:42:50 tonkachi kernel: [  707.759089] Registered led device:
> > iwl-phy0::radio
> > Feb 25 17:42:50 tonkachi kernel: [  707.759179] Registered led device:
> > iwl-phy0::assoc
> > Feb 25 17:42:50 tonkachi kernel: [  707.759412] Registered led device:
> > iwl-phy0::RX
> > Feb 25 17:42:50 tonkachi kernel: [  707.759572] Registered led device:
> > iwl-phy0::TX
> > 
> > 
> > 
> > but the disk does not register anymore :(
> 
> This is something Sarah should look into.  She's the main developer 
> behind xhci-hcd.

Sarah Sharp

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Thu, 25 Feb 2010, Sarah Sharp wrote:

> > > now, I unplug the USB DVD drive:
> > > 
> > > Feb 25 17:35:38 tonkachi kernel: [  276.374282] xhci_hcd 0000:02:00.0:
> > > WARN: transfer error on endpoint
> > > Feb 25 17:35:39 tonkachi kernel: [  276.728151] xhci_hcd 0000:02:00.0:
> > > WARN: transfer error on endpoint
> > > Feb 25 17:35:39 tonkachi kernel: [  276.728819] xhci_hcd 0000:02:00.0:
> > > WARN: transfer error on endpoint

Shouldn't there be some messages here about "USB disconnect"?  This 
suggests there's something wrong with the root hub.

> > > I plug it back in, with a DVD in the drive:
> > > 
> > > Feb 25 17:41:21 tonkachi kernel: [  618.701586] Registered led device:
> > > iwl-phy0::radio
> > > Feb 25 17:41:21 tonkachi kernel: [  618.701619] Registered led device:
> > > iwl-phy0::assoc
> > > Feb 25 17:41:21 tonkachi kernel: [  618.701649] Registered led device:
> > > iwl-phy0::RX
> > > Feb 25 17:41:21 tonkachi kernel: [  618.701674] Registered led device:
> > > iwl-phy0::TX
> > > Feb 25 17:41:21 tonkachi kernel: [  618.719536] usb 2-3: new high speed
> > > USB device using xhci_hcd and address 0
> > > Feb 25 17:41:21 tonkachi kernel: [  618.742028] usb 2-3: New USB device
> > > found, idVendor=058f, idProduct=6254
> > > Feb 25 17:41:21 tonkachi kernel: [  618.742034] usb 2-3: New USB device
> > > strings: Mfr=0, Product=0, SerialNumber=0
> > > Feb 25 17:41:21 tonkachi kernel: [  618.742155] usb 2-3: configuration
> > > #1 chosen from 1 choice
> > > Feb 25 17:41:21 tonkachi kernel: [  618.742168] usb 2-3: ep 0x81 -
> > > rounding interval to 2048 microframes

You must have plugged it into a different port this time, yes?

> That looks like a rather long polling interval.  Can you post the output
> of `lsusb -vvv -d 058f:6254`?

2048 microframes is 256 ms, the normal polling interval for hubs.

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Sarah Sharp]

On Thu, Feb 25, 2010 at 02:36:02PM -0500, Alan Stern wrote:
> On Thu, 25 Feb 2010, Sarah Sharp wrote:
> 
> > > > now, I unplug the USB DVD drive:
> > > > 
> > > > Feb 25 17:35:38 tonkachi kernel: [  276.374282] xhci_hcd 0000:02:00.0:
> > > > WARN: transfer error on endpoint
> > > > Feb 25 17:35:39 tonkachi kernel: [  276.728151] xhci_hcd 0000:02:00.0:
> > > > WARN: transfer error on endpoint
> > > > Feb 25 17:35:39 tonkachi kernel: [  276.728819] xhci_hcd 0000:02:00.0:
> > > > WARN: transfer error on endpoint
> 
> Shouldn't there be some messages here about "USB disconnect"?  This 
> suggests there's something wrong with the root hub.

True.  I can't tell exactly what's going on without
CONFIG_USB_XHCI_HCD_DEBUGGING.  It's possible the xHCI host never
notified the driver of the disconnect, or there's a bug in the xHCI hub
emulation code.

Sarah Sharp

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Alan Stern wrote:
> It is the driver for USB-3.0 controllers.  It's relatively new and not 
> as mature as the USB-2.0 drivers.
> 
> I'm a little surprised that it is running on your system.  Why would 
> you have USB-3.0 hardware?

I might - this is a brand new HP Envy 15 laptop, which seems to be 'too
new' for Linux in a number of ways (e.g. video card, with the latest
10.2 official AMD binary driver 'sort of' working, hardware raid
controller for SSD, which only the mainline grub can handle, WiFi card
that is only supported in 2.6.32.x, etc.)

actually, it has 3 USB ports - two of them seem to have these issues.
the third USB port, which is phyisically both a USB and en eSATA port,
seems to work as expected.

> This is something Sarah should look into.  She's the main developer 
> behind xhci-hcd.

thanks for CC'ing her in..


Sarah Sharp wrote:
> USB 3.0 hosts and devices are now available commercially.  I think the
> HP envy laptop has an integrated USB 3.0 host.  Ákos, which host
> controller do you have?  Is it a PCIe add-in card, a PCI express card,
> or a port on a laptop?

see above, these are two ports on the side of the laptop.

> The xHCI driver doesn't support PCI suspend, and it also doesn't support
> suspending devices under the xHCI host.  The xHCI hardware needs to do
> some extra work when a device is suspended, and I haven't added that API
> to the USB core yet.  In short, power management sucks under xHCI. :-/

for suspend, I seem to get along find with unloading / reloading the
xhci kernel module, as a workaround

> Oh, freezes are not good.  I wonder if the xHCI host is taking a long
> time to respond to a hardware command?  Can you turn on
> CONFIG_USB_XHCI_HCD_DEBUGGING and send me the dmesg when you plug in the
> device?

ok, I'll do that..

> Did you plug in the DVD device behind a USB hub?  Or is the hub a part
> of the device?

I didn't use a USB hub. I plugged in the USB DVD right into the USB port
on the laptop. the HP Envy 15 does not have a built-in optical drive,
but you can order an external USB DVD-RW drive as an option. this is
what I have.

> That looks like a rather long polling interval.  Can you post the output
> of `lsusb -vvv -d 058f:6254`?

sure, here you go:

# lsusb -vvv -d 058f:6254

Bus 002 Device 002: ID 058f:6254 Alcor Micro Corp. USB Hub
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass            9 Hub
  bDeviceSubClass         0 Unused
  bDeviceProtocol         1 Single TT
  bMaxPacketSize0        64
  idVendor           0x058f Alcor Micro Corp.
  idProduct          0x6254 USB Hub
  bcdDevice            1.00
  iManufacturer           0
  iProduct                0
  iSerial                 0
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength           25
    bNumInterfaces          1
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0xe0
      Self Powered
      Remote Wakeup
    MaxPower              100mA
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         9 Hub
      bInterfaceSubClass      0 Unused
      bInterfaceProtocol      0 Full speed (or root) hub
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0001  1x 1 bytes
        bInterval              12
Hub Descriptor:
  bLength               9
  bDescriptorType      41
  nNbrPorts             3
  wHubCharacteristic 0x0080
    Ganged power switching
    Ganged overcurrent protection
    TT think time 8 FS bits
    Port indicators
  bPwrOn2PwrGood       50 * 2 milli seconds
  bHubContrCurrent    100 milli Ampere
  DeviceRemovable    0x02
  PortPwrCtrlMask    0xff
 Hub Port Status:
   Port 1: 0000.0503 highspeed power enable connect
   Port 2: 0000.0100 power
   Port 3: 0000.0100 power
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            9 Hub
  bDeviceSubClass         0 Unused
  bDeviceProtocol         0 Full speed (or root) hub
  bMaxPacketSize0        64
  bNumConfigurations      1
Device Status:     0x0001
  Self Powered



though let me remind you that the same long delay happens when I plug in
other devices, like simple USB mice. also, if I plug in the same device
into the third USB port, it seems to work just fine. no 5 second freeze,
etc.

> Can you read the DVD at this point?

yes, after the first plug, it works as expected. after the unplug -
replug, it doesn't work. unless I unload the xhci module, and reload it.

> Did you unmount the DVD before you removed it?  I'm not sure what the
> VFS errors are, but it looks like VFS doesn't like you removing the
> disk.

IMHO it got automatically mounted by gnome... (I saw it on my desktop as
a DVD drive)


Alan Stern wrote:
> You must have plugged it into a different port this time, yes?

I might have used the different of the two proplematic USB ports..


Sarah Sharp wrote:
> True.  I can't tell exactly what's going on without
> CONFIG_USB_XHCI_HCD_DEBUGGING.  It's possible the xHCI host never
> notified the driver of the disconnect, or there's a bug in the xHCI hub
> emulation code.

I'm recompiling the kernel with the above configuration setting, and
will send you an output..

thanks for spending time on this issue...


BTW, any ideas on why suspend works with unloading xhci, but hibernate
not working?


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Thu, 25 Feb 2010, Ákos Maróy wrote:

> BTW, any ideas on why suspend works with unloading xhci, but hibernate
> not working?

That's a power management issue, not a USB problem.  Rafael may be able 
to help you.  You'll probably want to start a new email thread on the 
linux-pm mailing list.

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Sarah,

> True.  I can't tell exactly what's going on without
> CONFIG_USB_XHCI_HCD_DEBUGGING.  It's possible the xHCI host never
> notified the driver of the disconnect, or there's a bug in the xHCI hub
> emulation code.

after having turned this option on in the kernel, this is what I get
when plugging in the device:

Feb 25 23:32:14 tonkachi kernel: [  100.473783] Registered led device:
iwl-phy0::radio
Feb 25 23:32:14 tonkachi kernel: [  100.473812] Registered led device:
iwl-phy0::assoc
Feb 25 23:32:14 tonkachi kernel: [  100.473839] Registered led device:
iwl-phy0::RX
Feb 25 23:32:14 tonkachi kernel: [  100.473864] Registered led device:
iwl-phy0::TX
Feb 25 23:32:14 tonkachi kernel: [  100.497848] usb 2-4: new high speed
USB device using xhci_hcd and address 0
Feb 25 23:32:14 tonkachi kernel: [  100.520591] usb 2-4: New USB device
found, idVendor=058f, idProduct=6254
Feb 25 23:32:14 tonkachi kernel: [  100.520595] usb 2-4: New USB device
strings: Mfr=0, Product=0, SerialNumber=0
Feb 25 23:32:14 tonkachi kernel: [  100.520680] usb 2-4: configuration
#1 chosen from 1 choice
Feb 25 23:32:14 tonkachi kernel: [  100.520732] usb 2-4: ep 0x81 -
rounding interval to 2048 microframes
Feb 25 23:32:14 tonkachi kernel: [  100.522403] hub 2-4:1.0: USB hub found
Feb 25 23:32:14 tonkachi kernel: [  100.522930] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.523156] hub 2-4:1.0: 3 ports
detected
Feb 25 23:32:14 tonkachi kernel: [  100.825758] usb 2-4.1: new high
speed USB device using xhci_hcd and address 0
Feb 25 23:32:14 tonkachi kernel: [  100.848327] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.849375] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.850370] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.851366] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.851782] usb 2-4.1: New USB
device found, idVendor=152d, idProduct=2339
Feb 25 23:32:14 tonkachi kernel: [  100.851785] usb 2-4.1: New USB
device strings: Mfr=1, Product=2, SerialNumber=5
Feb 25 23:32:14 tonkachi kernel: [  100.851790] usb 2-4.1: Product: USB
to ATA/ATAPI Bridge
Feb 25 23:32:14 tonkachi kernel: [  100.851792] usb 2-4.1: Manufacturer:
JMicron
Feb 25 23:32:14 tonkachi kernel: [  100.851795] usb 2-4.1: SerialNumber:
6A1713351FFF
Feb 25 23:32:14 tonkachi kernel: [  100.851873] usb 2-4.1: configuration
#1 chosen from 1 choice
Feb 25 23:32:14 tonkachi kernel: [  100.854283] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.855037] xhci_hcd 0000:02:00.0:
WARN: short transfer on control ep
Feb 25 23:32:14 tonkachi kernel: [  100.879271] Initializing USB Mass
Storage driver...
Feb 25 23:32:14 tonkachi kernel: [  100.879988] scsi6 : SCSI emulation
for USB Mass Storage devices
Feb 25 23:32:14 tonkachi kernel: [  100.880141] usbcore: registered new
interface driver usb-storage
Feb 25 23:32:14 tonkachi kernel: [  100.880147] USB Mass Storage support
registered.
Feb 25 23:32:19 tonkachi kernel: [  105.884853] scsi 6:0:0:0: CD-ROM
        hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
Feb 25 23:32:19 tonkachi kernel: <0: `MEM_WRITE_DWORD(3'b000,
32'hffffc90000hi0 00000.1fevhc anl0d0i  02-:e0x  t2);
Feb 25 23:32:19 tonkachi kernel: x1.0:  _ca0 00000000 01000000 02038000
Feb 25 23:32:19 tonkachi kernel: x1.0: `MEM_W_c70 000000 f__h:had
c2c]:00-:e0x  t3);
Feb 25 23:32:19 tonkachi kernel: _tist us:i 00Tx] 5b78b073ndxh0.0
_c.]70h ]00t0:xhcf3) 754'hf);x.23000:02:00.0: `MEM_WRITE_DWORD(3'b000,
32'hffffc90000c7c024, 32'h8, 4'hf);
Feb 25 23:32:19 tonkachi kernel: 603n00nt 0<05.898876] xhci_hcd
0000:00h00MEM_WRITE_10 wn.8eh:0c>78 0 i_0 013Ue9:020)
Feb 25 23:32:19 tonkachi kernel: 02:00.i0h00.0: New dequeue pointer =
0x375b78d0 (DMA)
Feb 25 23:32:19 tonkachi kernel: 19
Feb 25 23:32:19 tonkachi kernel: 3d07` 300ee e_ i7c67 o5.899445] 9fc
Crned from h:0t8]__0td h096:: cs0000c63,v 005a/ed scsi  0
0dd00M_WRITE_DWORD(3'b000, 32'h50ns 01en2  ]]h00s0n/27 00670009[
903541] xhci0 00:_WRITE_DWORD(3'b000, 32'hffffc90000c7c024, 32'h8, 4'hf);
Feb 25 23:32:19 tonkachi kernel: n (D005.r0000:024 0
0dd00M_WRITE_DWORD(3'b000, 32'hffffc950ns0en2   ]]h00s0n/57 0067009[
907215] x0 0_WRITE_DWORD(3'b000, 32'hffffc90000c7c024, 32'h8, 4'hf);
Feb 25 23:32:19 tonkachi kernel: = 0i_hcd 0000:02:00.0:
`MEM_WRITE_DWORD(3'b000, 32'hffffc90000c7c808, 32'h3, 4'hf);
Feb 25 23:32:19 tonkachi kernel: n (D00090.rom0000:024 0
0dd00M_WRITE_DWORD(3'b000, 32'hffffc90000c50ns 09en2   ]]h00s0n/97
00670009[  910899] x0 00:_WRITE_DWORD(3'b000, 32'hffffc90000c7c024,
32'h8, 4'hf);
Feb 25 23:32:19 tonkachi kernel: T5nt d:h0  c:0s0n/57 00.0I67009[
916128] x0 00:0_WRITE_DWORD(3'b000, 32'hffffc90000c7c024, 32'h8, 4'hf);
Feb 25 23:32:19 tonkachi kernel: 6 3]0D0xhci8hci_
0000:02:040]1000:02:00.0: In handle_tx_event
Feb 25 23:32:19 tonkachi kernel: [  105.922881] xhci_hcd0hch0:
`MEM_WRI>f0OS _tx.0:c0990c_xh.0 8b0002c= 0>DMA)>[  105.92000000ht0lo>2f
:n0e0cf0c40.09400[._> ee_1<0a1r000c700.xhci_hcd 0000:02:00.0: Endpoint
state = 0x1
Feb 25 23:32:19 tonkachi kernel: 2:0:00.0: In xhci_handle_event
Feb 25 23:32:19 tonkachi kernel: 19b lnd 6] :000 020300.0ic_ nn
=f0x10[10105.926503] xhci_hcd 0000:02:00.0: Event ring deq =  02hc::;3(:
c7c.r80h 1_d7  10xx.]0477x.:EWx 6:00>[ 5750c>000.0: @37805720 375b7a30
00`7>ff5.936369] 7dx0 0_e0 :434h1:EWx 6:007>[300700000.0: @37805730 37
<h05.936744] xhci_hcd 0000:02:00.0: xhci_handle_event - OS owns TRB
Feb 25 23:32:19 tonkachi kernel:
Feb 25 23:32:19 tonkachi kernel: 025<)nE_DW0vev8 urb= 0x1
Feb 25 23:32:19 tonkachi kernel: <750.07<h05.937960] xhci_hcd
0000:02:00.0: xhci_handle_event - OS owns TRB
Feb 25 23:32:19 tonkachi kernel:
Feb 25 23:32:19 tonkachi kernel: 025<)[nE_D0veve8 urb= 0x1
Feb 25 23:32:19 tonkachi kernel:
Feb 25 23:32:19 tonkachi kernel: 025<)[nE_D0vev8 urb= 0x1
Feb 25 23:32:19 tonkachi kernel: <750c.07<h05.945270] xhci_hcd
0000:02:00.0: xhci_handle_event - OS owns TRB
Feb 25 23:32:19 tonkachi kernel: se0D]<7>090<c xh: `MEM0'vcd
0000:02:00.0: xhci_handle_event - calling handle_tx_event
Feb 25 23:32:19 tonkachi kernel: <0.0: @37805430 375b7ad0 0,T:7>xhih [c
Feb 25 23:32:19 tonkachi kernel: 7x140 i6b 6:00l38,0.0:3]
xhci_01ie5R'vecd 0000:02:00.0: xhci_handle_event - calling handle_tx_event
Feb 25 23:32:19 tonkachi kernel: se0( 0:020i_h t  dma_hcd 0000:02:00.0:
`M50537805460 375i8R 05c 005.0 7c0  c0c[f0:
Feb 25 23:32:19 tonkachi kernel: <370oinhcd 005107805470 375b7b00
00000000 01000000 02038001
Feb 25 23:32:19 tonkachi kernel: <37800ointhcd 0000:15.17805480
375d61f_,DI5d00019
Feb 25 23:32:19 tonkachi kernel: 1>d4x2d0i f: c
Feb 25 23:32:19 tonkachi kernel: 370oinhcd 0000:2i
Feb 25 23:32:19 tonkachi kernel: 00f[ 02:00.0: xhci_handle_event -
calling handle_tx_event
Feb 25 23:32:19 tonkachi kernel: 370ohcd 0051078054c0 375b7b30 00000000
01000000 02038001
Feb 25 23:32:20 tonkachi kernel: 37800ohcd 00005.178054d0 _,DI5.d 00009
Feb 25 23:32:20 tonkachi kernel: 1>d8x2d0i f:c
Feb 25 23:32:20 tonkachi kernel: 3780x4en = 0f1uh:5178054e0 375b7b40
00000000 01000000 0203800_,DI5d 00019
Feb 25 23:32:20 tonkachi kernel: 1>d62c0c f: Gc
Feb 25 23:32:20 tonkachi kernel: 37800oinhcd 0000:5.178054f0 375b7b50
00000000 01000000 02038001
Feb 25 23:32:20 tonkachi kernel: 1>d3x2c0c f: c
Feb 25 23:32:20 tonkachi kernel: 37800ohcd 0000:02:00.0: `M5.17805500
_,DIn5d00029
Feb 25 23:32:20 tonkachi kernel: 1>d8x2d0i f:
Feb 25 23:32:20 tonkachi kernel: 3780ohcd 00084nt0'3n 0000:02:00.0:
xhci_handle_event - calling handle_tx_event
Feb 25 23:32:20 tonkachi kernel: 60#hc
Feb 25 23:32:20 tonkachi kernel: : d A)  105.965349] xhci_hcd0cic:
`MEM_WR[c.S1tx00i
Feb 25 23:32:20 tonkachi kernel: 669dh8c001,a0:7 0[MA[  10hh0:
`MEM_WRITE_DWORD(3'b000, 32'hffffc90000c7c024, 32'h8, 4'hf);
Feb 25 23:32:20 tonkachi kernel: [  106.005103] xhci_hcd 0000:02:00.0:
WARN: Stalled endpoint
Feb 25 23:32:22 tonkachi kernel: <7008.h8Dhr:0:0248 ]0 158e 3x)
0nsf:02:00.0: Event ring deq =t867n = 13, sa008hc11Dhr:0:0209 ]0 198pe
00s)n:02:0t97cn = 31, status = 0
Feb 25 23:32:22 tonkachi kernel: 0i4<1= TfC (f>es uhcd 0000:  f86c0, len
= 18, status = 0



with un-plugging, I get:

Feb 25 23:33:07 tonkachi kernel: [  153.205311] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 23:33:08 tonkachi kernel: [  154.008265] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint
Feb 25 23:33:08 tonkachi kernel: [  154.008995] xhci_hcd 0000:02:00.0:
WARN: transfer error on endpoint



at this point, rmmod xhci doesn't even work anymore, I get stuff during
/ around the rmmod like:

Feb 25 23:34:24 tonkachi kernel: [  230.133711] xhci_hcd 0000:02:00.0:
remove, state 1
Feb 25 23:34:24 tonkachi kernel: [  230.133727] usb usb2: USB
disconnect, address 1
Feb 25 23:34:24 tonkachi kernel: [  230.133731] usb 2-4: USB disconnect,
address 2
Feb 25 23:34:24 tonkachi kernel: [  230.133735] usb 2-4.1: USB
disconnect, address 3



at the end, with rmmod still not returning, but doing a re-plug, I get:


Feb 25 23:36:37 tonkachi kernel: [  363.295298] rmmod         D
ffff88002834fa28     0  2818   2802 0x00000004
Feb 25 23:36:37 tonkachi kernel: [  363.295307]  ffff88022f581b88
0000000000000086 0000000000000000 0000000000000282
Feb 25 23:36:37 tonkachi kernel: [  363.295315]  00000000fffffffe
ffffffff81a0bf78 ffff88023fc3c8a0 00000000ffffe4be
Feb 25 23:36:37 tonkachi kernel: [  363.295323]  ffff8802332403c0
ffff88022f581fd8 000000000000fa28 ffff8802332403c0
Feb 25 23:36:37 tonkachi kernel: [  363.295331] Call Trace:
Feb 25 23:36:37 tonkachi kernel: [  363.295344]  [<ffffffff813b3ff5>]
usb_kill_urb+0x85/0xc0
Feb 25 23:36:37 tonkachi kernel: [  363.295353]  [<ffffffff8107d8b0>] ?
autoremove_wake_function+0x0/0x40
Feb 25 23:36:37 tonkachi kernel: [  363.295360]  [<ffffffff813b43c6>] ?
usb_get_urb+0x16/0x20
Feb 25 23:36:37 tonkachi kernel: [  363.295367]  [<ffffffff813b27db>]
usb_hcd_flush_endpoint+0xcb/0x1b0
Feb 25 23:36:37 tonkachi kernel: [  363.295374]  [<ffffffff813b4d18>]
usb_disable_endpoint+0x58/0x90
Feb 25 23:36:37 tonkachi kernel: [  363.295381]  [<ffffffff813b4dd9>]
usb_disable_device+0x89/0x1f0
Feb 25 23:36:37 tonkachi kernel: [  363.295388]  [<ffffffff813adc3d>]
usb_disconnect+0xfd/0x180
Feb 25 23:36:37 tonkachi kernel: [  363.295394]  [<ffffffff813adbff>]
usb_disconnect+0xbf/0x180
Feb 25 23:36:37 tonkachi kernel: [  363.295400]  [<ffffffff813b1a5d>]
usb_remove_hcd+0xcd/0x130
Feb 25 23:36:37 tonkachi kernel: [  363.295408]  [<ffffffff813c2236>]
usb_hcd_pci_remove+0x26/0xa0
Feb 25 23:36:37 tonkachi kernel: [  363.295416]  [<ffffffff812a0fdf>]
pci_device_remove+0x2f/0x60
Feb 25 23:36:37 tonkachi kernel: [  363.295433]  [<ffffffff81334bd3>]
__device_release_driver+0x53/0xb0
Feb 25 23:36:37 tonkachi kernel: [  363.295440]  [<ffffffff81334cf8>]
driver_detach+0xc8/0xd0
Feb 25 23:36:37 tonkachi kernel: [  363.295448]  [<ffffffff81333c65>]
bus_remove_driver+0x85/0xe0
Feb 25 23:36:37 tonkachi kernel: [  363.295456]  [<ffffffff813352ba>]
driver_unregister+0x5a/0x90
Feb 25 23:36:37 tonkachi kernel: [  363.295464]  [<ffffffff812a12d0>]
pci_unregister_driver+0x40/0xb0
Feb 25 23:36:37 tonkachi kernel: [  363.295476]  [<ffffffffa0048b80>]
xhci_unregister_pci+0x10/0x20 [xhci]
Feb 25 23:36:37 tonkachi kernel: [  363.295485]  [<ffffffffa004e459>]
xhci_hcd_cleanup+0x9/0xb [xhci]
Feb 25 23:36:37 tonkachi kernel: [  363.295493]  [<ffffffff81095768>]
sys_delete_module+0x1a8/0x270
Feb 25 23:36:37 tonkachi kernel: [  363.295500]  [<ffffffff81081bd9>] ?
up_read+0x9/0x10
Feb 25 23:36:37 tonkachi kernel: [  363.295510]  [<ffffffff81011f82>]
system_call_fastpath+0x16/0x1b




please let me know what other debugging I should do..


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Sarah Sharp]

On Thu, Feb 25, 2010 at 11:37:36PM +0100, Ákos Maróy wrote:
> Sarah,
> 
> > True.  I can't tell exactly what's going on without
> > CONFIG_USB_XHCI_HCD_DEBUGGING.  It's possible the xHCI host never
> > notified the driver of the disconnect, or there's a bug in the xHCI hub
> > emulation code.
> 
> after having turned this option on in the kernel, this is what I get
> when plugging in the device:
> 
> Feb 25 23:32:14 tonkachi kernel: [  100.473783] Registered led device:
> iwl-phy0::radio
> Feb 25 23:32:14 tonkachi kernel: [  100.473812] Registered led device:
> iwl-phy0::assoc
> Feb 25 23:32:14 tonkachi kernel: [  100.473839] Registered led device:
> iwl-phy0::RX
> Feb 25 23:32:14 tonkachi kernel: [  100.473864] Registered led device:
> iwl-phy0::TX
> Feb 25 23:32:14 tonkachi kernel: [  100.497848] usb 2-4: new high speed
> USB device using xhci_hcd and address 0
> Feb 25 23:32:14 tonkachi kernel: [  100.520591] usb 2-4: New USB device
> found, idVendor=058f, idProduct=6254
> Feb 25 23:32:14 tonkachi kernel: [  100.520595] usb 2-4: New USB device
> strings: Mfr=0, Product=0, SerialNumber=0
> Feb 25 23:32:14 tonkachi kernel: [  100.520680] usb 2-4: configuration
> #1 chosen from 1 choice
> Feb 25 23:32:14 tonkachi kernel: [  100.520732] usb 2-4: ep 0x81 -
> rounding interval to 2048 microframes
> Feb 25 23:32:14 tonkachi kernel: [  100.522403] hub 2-4:1.0: USB hub found
> Feb 25 23:32:14 tonkachi kernel: [  100.522930] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.523156] hub 2-4:1.0: 3 ports
> detected
> Feb 25 23:32:14 tonkachi kernel: [  100.825758] usb 2-4.1: new high
> speed USB device using xhci_hcd and address 0
> Feb 25 23:32:14 tonkachi kernel: [  100.848327] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.849375] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.850370] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.851366] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.851782] usb 2-4.1: New USB
> device found, idVendor=152d, idProduct=2339
> Feb 25 23:32:14 tonkachi kernel: [  100.851785] usb 2-4.1: New USB
> device strings: Mfr=1, Product=2, SerialNumber=5
> Feb 25 23:32:14 tonkachi kernel: [  100.851790] usb 2-4.1: Product: USB
> to ATA/ATAPI Bridge
> Feb 25 23:32:14 tonkachi kernel: [  100.851792] usb 2-4.1: Manufacturer:
> JMicron
> Feb 25 23:32:14 tonkachi kernel: [  100.851795] usb 2-4.1: SerialNumber:
> 6A1713351FFF
> Feb 25 23:32:14 tonkachi kernel: [  100.851873] usb 2-4.1: configuration
> #1 chosen from 1 choice
> Feb 25 23:32:14 tonkachi kernel: [  100.854283] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.855037] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 25 23:32:14 tonkachi kernel: [  100.879271] Initializing USB Mass
> Storage driver...
> Feb 25 23:32:14 tonkachi kernel: [  100.879988] scsi6 : SCSI emulation
> for USB Mass Storage devices
> Feb 25 23:32:14 tonkachi kernel: [  100.880141] usbcore: registered new
> interface driver usb-storage
> Feb 25 23:32:14 tonkachi kernel: [  100.880147] USB Mass Storage support
> registered.
> Feb 25 23:32:19 tonkachi kernel: [  105.884853] scsi 6:0:0:0: CD-ROM
>         hp       DVDRAM GT20L     DC05 PQ: 0 ANSI: 0
> Feb 25 23:32:19 tonkachi kernel: <0: `MEM_WRITE_DWORD(3'b000,
> 32'hffffc90000hi0 00000.1fevhc anl0d0i  02-:e0x  t2);

> Feb 25 23:32:19 tonkachi kernel: x1.0:  _ca0 00000000 01000000 02038000
> Feb 25 23:32:19 tonkachi kernel: x1.0: `MEM_W_c70 000000 f__h:had
> c2c]:00-:e0x  t3);
> Feb 25 23:32:19 tonkachi kernel: _tist us:i 00Tx] 5b78b073ndxh0.0
> _c.]70h ]00t0:xhcf3) 754'hf);x.23000:02:00.0: `MEM_WRITE_DWORD(3'b000,
> 32'hffffc90000c7c024, 32'h8, 4'hf);
> Feb 25 23:32:19 tonkachi kernel: 603n00nt 0<05.898876] xhci_hcd
> 0000:00h00MEM_WRITE_10 wn.8eh:0c>78 0 i_0 013Ue9:020)
> Feb 25 23:32:19 tonkachi kernel: 02:00.i0h00.0: New dequeue pointer =
> 0x375b78d0 (DMA)
> Feb 25 23:32:19 tonkachi kernel: 19
> Feb 25 23:32:19 tonkachi kernel: 3d07` 300ee e_ i7c67 o5.899445] 9fc

It looks like you're getting log corruption from the xHCI driver being
too verbose now. :(  I've been meaning to make a log level patch for the
driver and cut out the less-than-useful bits for while.  Let me do a
quick pass at that so we can get the interesting information.

> with un-plugging, I get:
> 
> Feb 25 23:33:07 tonkachi kernel: [  153.205311] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 23:33:08 tonkachi kernel: [  154.008265] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint
> Feb 25 23:33:08 tonkachi kernel: [  154.008995] xhci_hcd 0000:02:00.0:
> WARN: transfer error on endpoint

There should be a lot more debugging here.  Perhaps you were collecting
only the warning-level kernel messages?  Did you send the full dmesg
from /var/log/kern.log or run `dmesg -n 8` before capturing the dmesg
input?

Actually, I wonder if 2.6.32 stable needs commit bcef3fd from 2.6.33.
If the xHCI driver wasn't cleaning up the endpoint rings properly after
a transfer error, I suppose the hardware could get wedged.

> at this point, rmmod xhci doesn't even work anymore, I get stuff during
> / around the rmmod like:
> 
> Feb 25 23:34:24 tonkachi kernel: [  230.133711] xhci_hcd 0000:02:00.0:
> remove, state 1

Aw, man, it looks like your xHCI disconnected from the bus.  Something
was seriously wrong with the hardware.  Still, the xHCI driver should
have failed gracefully in that case.  That should have been handled by
commits c526d0d, e34b2fb, and e4ab05d, which are in 2.6.32 and 2.6.33.

> Feb 25 23:34:24 tonkachi kernel: [  230.133727] usb usb2: USB
> disconnect, address 1
> Feb 25 23:34:24 tonkachi kernel: [  230.133731] usb 2-4: USB disconnect,
> address 2
> Feb 25 23:34:24 tonkachi kernel: [  230.133735] usb 2-4.1: USB
> disconnect, address 3
> 
> 
> 
> at the end, with rmmod still not returning, but doing a re-plug, I get:
> 
> 
> Feb 25 23:36:37 tonkachi kernel: [  363.295298] rmmod         D
> ffff88002834fa28     0  2818   2802 0x00000004
> Feb 25 23:36:37 tonkachi kernel: [  363.295307]  ffff88022f581b88
> 0000000000000086 0000000000000000 0000000000000282
> Feb 25 23:36:37 tonkachi kernel: [  363.295315]  00000000fffffffe
> ffffffff81a0bf78 ffff88023fc3c8a0 00000000ffffe4be
> Feb 25 23:36:37 tonkachi kernel: [  363.295323]  ffff8802332403c0
> ffff88022f581fd8 000000000000fa28 ffff8802332403c0
> Feb 25 23:36:37 tonkachi kernel: [  363.295331] Call Trace:
> Feb 25 23:36:37 tonkachi kernel: [  363.295344]  [<ffffffff813b3ff5>]
> usb_kill_urb+0x85/0xc0
> Feb 25 23:36:37 tonkachi kernel: [  363.295353]  [<ffffffff8107d8b0>] ?
> autoremove_wake_function+0x0/0x40
> Feb 25 23:36:37 tonkachi kernel: [  363.295360]  [<ffffffff813b43c6>] ?
> usb_get_urb+0x16/0x20
> Feb 25 23:36:37 tonkachi kernel: [  363.295367]  [<ffffffff813b27db>]
> usb_hcd_flush_endpoint+0xcb/0x1b0
> Feb 25 23:36:37 tonkachi kernel: [  363.295374]  [<ffffffff813b4d18>]
> usb_disable_endpoint+0x58/0x90
> Feb 25 23:36:37 tonkachi kernel: [  363.295381]  [<ffffffff813b4dd9>]
> usb_disable_device+0x89/0x1f0
> Feb 25 23:36:37 tonkachi kernel: [  363.295388]  [<ffffffff813adc3d>]
> usb_disconnect+0xfd/0x180
> Feb 25 23:36:37 tonkachi kernel: [  363.295394]  [<ffffffff813adbff>]
> usb_disconnect+0xbf/0x180
> Feb 25 23:36:37 tonkachi kernel: [  363.295400]  [<ffffffff813b1a5d>]
> usb_remove_hcd+0xcd/0x130
> Feb 25 23:36:37 tonkachi kernel: [  363.295408]  [<ffffffff813c2236>]
> usb_hcd_pci_remove+0x26/0xa0
> Feb 25 23:36:37 tonkachi kernel: [  363.295416]  [<ffffffff812a0fdf>]
> pci_device_remove+0x2f/0x60
> Feb 25 23:36:37 tonkachi kernel: [  363.295433]  [<ffffffff81334bd3>]
> __device_release_driver+0x53/0xb0
> Feb 25 23:36:37 tonkachi kernel: [  363.295440]  [<ffffffff81334cf8>]
> driver_detach+0xc8/0xd0
> Feb 25 23:36:37 tonkachi kernel: [  363.295448]  [<ffffffff81333c65>]
> bus_remove_driver+0x85/0xe0
> Feb 25 23:36:37 tonkachi kernel: [  363.295456]  [<ffffffff813352ba>]
> driver_unregister+0x5a/0x90
> Feb 25 23:36:37 tonkachi kernel: [  363.295464]  [<ffffffff812a12d0>]
> pci_unregister_driver+0x40/0xb0
> Feb 25 23:36:37 tonkachi kernel: [  363.295476]  [<ffffffffa0048b80>]
> xhci_unregister_pci+0x10/0x20 [xhci]
> Feb 25 23:36:37 tonkachi kernel: [  363.295485]  [<ffffffffa004e459>]
> xhci_hcd_cleanup+0x9/0xb [xhci]
> Feb 25 23:36:37 tonkachi kernel: [  363.295493]  [<ffffffff81095768>]
> sys_delete_module+0x1a8/0x270
> Feb 25 23:36:37 tonkachi kernel: [  363.295500]  [<ffffffff81081bd9>] ?
> up_read+0x9/0x10
> Feb 25 23:36:37 tonkachi kernel: [  363.295510]  [<ffffffff81011f82>]
> system_call_fastpath+0x16/0x1b

If the hardware wasn't responding properly to commands, then URBs
wouldn't have been able to be killed, the USB core would have sat around
waiting on those URBs, and rmmod could never exit.  I need a more
detailed log to figure out exactly why the hardware is wedged though.
Let me make the less-verbose debugging patch so you don't get log
corruption, and then we'll see what's going on.

Sarah Sharp

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Edward Shao]

Hi Ákos~

On Thu, Feb 25, 2010 at 6:36 AM, Ákos Maróy <akos@maroy.hu> wrote:
> Alan,
>
>> You can get more information if you enable CONFIG_USB_DEBUG in your
>> kernel configuration.  The most likely explanation is that the suspend
>> failed because one of the ports on that root hub issued a wakeup
>> request.
>
> I tried, and this is what I seem to be getting now:
>
>
> Feb 24 23:28:52 tonkachi kernel: [  348.733460] PM: Syncing filesystems ...
> Feb 24 23:28:52 tonkachi kernel: [  348.903106] done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903123] Freezing user space
> processes ... (elapsed 0.00 seconds) done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903808] Freezing remaining
> freezable tasks ... (elapsed 0.00 seconds) done.
> Feb 24 23:28:52 tonkachi kernel: [  348.903952] Suspending console(s)
> (use no_console_suspend to debug)
> Feb 24 23:28:52 tonkachi kernel: [  348.985903] xhci_hcd 0000:02:00.0:
> WARN: short transfer on control ep
> Feb 24 23:28:52 tonkachi kernel: [  348.987274] PM: resume devices took
> 0.060 seconds
> Feb 24 23:28:52 tonkachi kernel: [  348.987371] Restarting tasks ...
> Feb 24 23:28:52 tonkachi kernel: [  348.988165] done.
>
>
> though I don't see the pm_op() error log anymore..
>
> would this make sense?
>
> actually, the whole USB susbsystem seems to be very fragile - I plug in
> a USB device, and the whole system freezes for about 5 seconds or more.
> then the device is registered (for example, a mouse). but I unplug and
> re-plug, and the device doesn't work anymore...

the whole system freezes for about 5 seconds or more?
I meet a very similar issue before on HP Envy 15 laptop when I plugged
usb device on xhci port.
My problem was BIOS still controlled xhci host controller.
Maybe you can try this patch.
http://markmail.org/message/vqcbzks4gnbrlir3

>
> or I plug in an external USB DVD drive - but if I unplug it, it is still
> listed in lsusb..
>
>
> Akos
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>

-- 
Best Regards,
Edward

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Alan Stern]

On Thu, 25 Feb 2010, Sarah Sharp wrote:

> > at this point, rmmod xhci doesn't even work anymore, I get stuff during
> > / around the rmmod like:
> > 
> > Feb 25 23:34:24 tonkachi kernel: [  230.133711] xhci_hcd 0000:02:00.0:
> > remove, state 1
> 
> Aw, man, it looks like your xHCI disconnected from the bus.  Something
> was seriously wrong with the hardware.

Why do you say that?  Isn't this exactly the sort of thing you expect 
to see in the log when xhci-hcd is unloaded?

Alan Stern

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Sarah Sharp]

On Fri, Feb 26, 2010 at 11:12:50AM -0500, Alan Stern wrote:
> On Thu, 25 Feb 2010, Sarah Sharp wrote:
> 
> > > at this point, rmmod xhci doesn't even work anymore, I get stuff during
> > > / around the rmmod like:
> > > 
> > > Feb 25 23:34:24 tonkachi kernel: [  230.133711] xhci_hcd 0000:02:00.0:
> > > remove, state 1
> > 
> > Aw, man, it looks like your xHCI disconnected from the bus.  Something
> > was seriously wrong with the hardware.
> 
> Why do you say that?  Isn't this exactly the sort of thing you expect 
> to see in the log when xhci-hcd is unloaded?

Yes, I forgot he was unloading the driver.  That's normal then.

Sarah Sharp

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Sarah,

> Actually, I wonder if 2.6.32 stable needs commit bcef3fd from 2.6.33.
> If the xHCI driver wasn't cleaning up the endpoint rings properly after
> a transfer error, I suppose the hardware could get wedged.

I see. where would I get this commit from? I have to stick with 2.6.32,
as I'm using the binary ATI video driver, which doesn't work with 2.6.33...

> If the hardware wasn't responding properly to commands, then URBs
> wouldn't have been able to be killed, the USB core would have sat around
> waiting on those URBs, and rmmod could never exit.  I need a more
> detailed log to figure out exactly why the hardware is wedged though.
> Let me make the less-verbose debugging patch so you don't get log
> corruption, and then we'll see what's going on.

let me know how I can use this..


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Edward,

> the whole system freezes for about 5 seconds or more?
> I meet a very similar issue before on HP Envy 15 laptop when I plugged
> usb device on xhci port.
> My problem was BIOS still controlled xhci host controller.
> Maybe you can try this patch.
> http://markmail.org/message/vqcbzks4gnbrlir3

thanks, indeed, this seems to have solved the freezing issue!


Akos

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Sarah Sharp]

[-- Attachment #1: Type: text/plain, Size: 1894 bytes --]

On Sat, Feb 27, 2010 at 09:02:11AM +0100, Ákos Maróy wrote:
> Sarah,
> 
> > Actually, I wonder if 2.6.32 stable needs commit bcef3fd from 2.6.33.
> > If the xHCI driver wasn't cleaning up the endpoint rings properly after
> > a transfer error, I suppose the hardware could get wedged.
> 
> I see. where would I get this commit from? I have to stick with 2.6.32,
> as I'm using the binary ATI video driver, which doesn't work with 2.6.33...
> 
> > If the hardware wasn't responding properly to commands, then URBs
> > wouldn't have been able to be killed, the USB core would have sat around
> > waiting on those URBs, and rmmod could never exit.  I need a more
> > detailed log to figure out exactly why the hardware is wedged though.
> > Let me make the less-verbose debugging patch so you don't get log
> > corruption, and then we'll see what's going on.
> 
> let me know how I can use this..

Akos,

I've attached two patches that apply against 2.6.32.9.  The first limits
the amount of debugging from the xHCI driver to prevent log file
corruption.  The second is a backport of the commit bcef3fd from Linus'
2.6.33 tree.  I think this is the fix you need, but I can't be sure
until I see the complete log from the first patch.

Please apply the first patch, recompile with
CONFIG_USB_XHCI_HCD_DEBUGGING=y, and send me the results of `tail -f
/var/log/kern.log | tee /tmp/xhci-hp-envy-15.log`.  You'll need to load
the xHCI driver with the log_level module parameter set to 1095, like
so:

sudo insmod drivers/usb/host/xhci.ko log_level=1095

That will limit the debugging to output that relates to errors on
transfer events, hardware quirks, commands sent to the hardware, and
port status reporting.

When the driver is running, try an unplug of your USB DVD device and an
xHCI driver module remove.

Then apply the second patch, recompile, and do the same experiment.

Thanks,
Sarah Sharp

[-- Attachment #2: 0001-xhci-Add-logging-levels-and-reduce-excessive-verbosi.patch --]
[-- Type: text/x-diff, Size: 92365 bytes --]

>From fa51d5ea582c988f0f8f202749fbc42382b224ba Mon Sep 17 00:00:00 2001
From: Sarah Sharp <sarah.a.sharp@linux.intel.com>
Date: Mon, 1 Mar 2010 16:23:53 -0800
Subject: [PATCH 1/2] xhci: Add logging levels and reduce excessive verbosity.

Signed-off-by: Sarah Sharp <sarah.a.sharp@linux.intel.com>
---
 drivers/usb/host/xhci-dbg.c  |  280 ++++++++++++++++++++++++++++--------------
 drivers/usb/host/xhci-hcd.c  |  263 ++++++++++++++++++++-------------------
 drivers/usb/host/xhci-hub.c  |   21 +++-
 drivers/usb/host/xhci-mem.c  |   87 ++++---------
 drivers/usb/host/xhci-pci.c  |   15 +--
 drivers/usb/host/xhci-ring.c |  213 ++++++++++++++++----------------
 drivers/usb/host/xhci.h      |   31 ++++-
 7 files changed, 500 insertions(+), 410 deletions(-)

diff --git a/drivers/usb/host/xhci-dbg.c b/drivers/usb/host/xhci-dbg.c
index 33128d5..ae71c56 100644
--- a/drivers/usb/host/xhci-dbg.c
+++ b/drivers/usb/host/xhci-dbg.c
@@ -30,80 +30,106 @@ void xhci_dbg_regs(struct xhci_hcd *xhci)
 {
 	u32 temp;
 
-	xhci_dbg(xhci, "// xHCI capability registers at %p:\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"xHCI capability registers at %p:\n",
 			xhci->cap_regs);
 	temp = xhci_readl(xhci, &xhci->cap_regs->hc_capbase);
-	xhci_dbg(xhci, "// @%p = 0x%x (CAPLENGTH AND HCIVERSION)\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"@%p = 0x%x (CAPLENGTH AND HCIVERSION)\n",
 			&xhci->cap_regs->hc_capbase, temp);
-	xhci_dbg(xhci, "//   CAPLENGTH: 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"   CAPLENGTH: 0x%x\n",
 			(unsigned int) HC_LENGTH(temp));
 #if 0
 	xhci_dbg(xhci, "//   HCIVERSION: 0x%x\n",
 			(unsigned int) HC_VERSION(temp));
 #endif
 
-	xhci_dbg(xhci, "// xHCI operational registers at %p:\n", xhci->op_regs);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+		       "xHCI operational registers at %p:\n", xhci->op_regs);
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->run_regs_off);
-	xhci_dbg(xhci, "// @%p = 0x%x RTSOFF\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+		       "@%p = 0x%x RTSOFF\n",
 			&xhci->cap_regs->run_regs_off,
 			(unsigned int) temp & RTSOFF_MASK);
-	xhci_dbg(xhci, "// xHCI runtime registers at %p:\n", xhci->run_regs);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"xHCI runtime registers at %p:\n", xhci->run_regs);
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->db_off);
-	xhci_dbg(xhci, "// @%p = 0x%x DBOFF\n", &xhci->cap_regs->db_off, temp);
-	xhci_dbg(xhci, "// Doorbell array at %p:\n", xhci->dba);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"@%p = 0x%x DBOFF\n", &xhci->cap_regs->db_off, temp);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"Doorbell array at %p:\n", xhci->dba);
 }
 
 static void xhci_print_cap_regs(struct xhci_hcd *xhci)
 {
 	u32 temp;
 
-	xhci_dbg(xhci, "xHCI capability registers at %p:\n", xhci->cap_regs);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"xHCI capability registers at %p:\n", xhci->cap_regs);
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->hc_capbase);
-	xhci_dbg(xhci, "CAPLENGTH AND HCIVERSION 0x%x:\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"CAPLENGTH AND HCIVERSION 0x%x:\n",
 			(unsigned int) temp);
-	xhci_dbg(xhci, "CAPLENGTH: 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"CAPLENGTH: 0x%x\n",
 			(unsigned int) HC_LENGTH(temp));
-	xhci_dbg(xhci, "HCIVERSION: 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"HCIVERSION: 0x%x\n",
 			(unsigned int) HC_VERSION(temp));
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->hcs_params1);
-	xhci_dbg(xhci, "HCSPARAMS 1: 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"HCSPARAMS 1: 0x%x\n",
 			(unsigned int) temp);
-	xhci_dbg(xhci, "  Max device slots: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Max device slots: %u\n",
 			(unsigned int) HCS_MAX_SLOTS(temp));
-	xhci_dbg(xhci, "  Max interrupters: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Max interrupters: %u\n",
 			(unsigned int) HCS_MAX_INTRS(temp));
-	xhci_dbg(xhci, "  Max ports: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Max ports: %u\n",
 			(unsigned int) HCS_MAX_PORTS(temp));
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->hcs_params2);
-	xhci_dbg(xhci, "HCSPARAMS 2: 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"HCSPARAMS 2: 0x%x\n",
 			(unsigned int) temp);
-	xhci_dbg(xhci, "  Isoc scheduling threshold: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Isoc scheduling threshold: %u\n",
 			(unsigned int) HCS_IST(temp));
-	xhci_dbg(xhci, "  Maximum allowed segments in event ring: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Maximum allowed segments in event ring: %u\n",
 			(unsigned int) HCS_ERST_MAX(temp));
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->hcs_params3);
-	xhci_dbg(xhci, "HCSPARAMS 3 0x%x:\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"HCSPARAMS 3 0x%x:\n",
 			(unsigned int) temp);
-	xhci_dbg(xhci, "  Worst case U1 device exit latency: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Worst case U1 device exit latency: %u\n",
 			(unsigned int) HCS_U1_LATENCY(temp));
-	xhci_dbg(xhci, "  Worst case U2 device exit latency: %u\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Worst case U2 device exit latency: %u\n",
 			(unsigned int) HCS_U2_LATENCY(temp));
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->hcc_params);
-	xhci_dbg(xhci, "HCC PARAMS 0x%x:\n", (unsigned int) temp);
-	xhci_dbg(xhci, "  HC generates %s bit addresses\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"HCC PARAMS 0x%x:\n", (unsigned int) temp);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  HC generates %s bit addresses\n",
 			HCC_64BIT_ADDR(temp) ? "64" : "32");
 	/* FIXME */
-	xhci_dbg(xhci, "  FIXME: more HCCPARAMS debugging\n");
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  FIXME: more HCCPARAMS debugging\n");
 
 	temp = xhci_readl(xhci, &xhci->cap_regs->run_regs_off);
-	xhci_dbg(xhci, "RTSOFF 0x%x:\n", temp & RTSOFF_MASK);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"RTSOFF 0x%x:\n", temp & RTSOFF_MASK);
 }
 
 static void xhci_print_command_reg(struct xhci_hcd *xhci)
@@ -111,16 +137,22 @@ static void xhci_print_command_reg(struct xhci_hcd *xhci)
 	u32 temp;
 
 	temp = xhci_readl(xhci, &xhci->op_regs->command);
-	xhci_dbg(xhci, "USBCMD 0x%x:\n", temp);
-	xhci_dbg(xhci, "  HC is %s\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"USBCMD 0x%x:\n", temp);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  HC is %s\n",
 			(temp & CMD_RUN) ? "running" : "being stopped");
-	xhci_dbg(xhci, "  HC has %sfinished hard reset\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  HC has %sfinished hard reset\n",
 			(temp & CMD_RESET) ? "not " : "");
-	xhci_dbg(xhci, "  Event Interrupts %s\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Event Interrupts %s\n",
 			(temp & CMD_EIE) ? "enabled " : "disabled");
-	xhci_dbg(xhci, "  Host System Error Interrupts %s\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Host System Error Interrupts %s\n",
 			(temp & CMD_EIE) ? "enabled " : "disabled");
-	xhci_dbg(xhci, "  HC has %sfinished light reset\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  HC has %sfinished light reset\n",
 			(temp & CMD_LRESET) ? "not " : "");
 }
 
@@ -129,18 +161,23 @@ static void xhci_print_status(struct xhci_hcd *xhci)
 	u32 temp;
 
 	temp = xhci_readl(xhci, &xhci->op_regs->status);
-	xhci_dbg(xhci, "USBSTS 0x%x:\n", temp);
-	xhci_dbg(xhci, "  Event ring is %sempty\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"USBSTS 0x%x:\n", temp);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  Event ring is %sempty\n",
 			(temp & STS_EINT) ? "not " : "");
-	xhci_dbg(xhci, "  %sHost System Error\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %sHost System Error\n",
 			(temp & STS_FATAL) ? "WARNING: " : "No ");
-	xhci_dbg(xhci, "  HC is %s\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  HC is %s\n",
 			(temp & STS_HALT) ? "halted" : "running");
 }
 
 static void xhci_print_op_regs(struct xhci_hcd *xhci)
 {
-	xhci_dbg(xhci, "xHCI operational registers at %p:\n", xhci->op_regs);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"xHCI operational registers at %p:\n", xhci->op_regs);
 	xhci_print_command_reg(xhci);
 	xhci_print_status(xhci);
 }
@@ -161,7 +198,8 @@ static void xhci_print_ports(struct xhci_hcd *xhci)
 	addr = &xhci->op_regs->port_status_base;
 	for (i = 0; i < ports; i++) {
 		for (j = 0; j < NUM_PORT_REGS; ++j) {
-			xhci_dbg(xhci, "%p port %s reg = 0x%x\n",
+			xhci_dbg(xhci, (XHCI_LOG_PORTS | XHCI_LOG_REGS),
+					"%p port %s reg = 0x%x\n",
 					addr, names[j],
 					(unsigned int) xhci_readl(xhci, addr));
 			addr++;
@@ -180,35 +218,42 @@ void xhci_print_ir_set(struct xhci_hcd *xhci, struct xhci_intr_reg *ir_set, int
 	if (temp == XHCI_INIT_VALUE)
 		return;
 
-	xhci_dbg(xhci, "  %p: ir_set[%i]\n", ir_set, set_num);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set[%i]\n", ir_set, set_num);
 
-	xhci_dbg(xhci, "  %p: ir_set.pending = 0x%x\n", addr,
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set.pending = 0x%x\n", addr,
 			(unsigned int)temp);
 
 	addr = &ir_set->irq_control;
 	temp = xhci_readl(xhci, addr);
-	xhci_dbg(xhci, "  %p: ir_set.control = 0x%x\n", addr,
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set.control = 0x%x\n", addr,
 			(unsigned int)temp);
 
 	addr = &ir_set->erst_size;
 	temp = xhci_readl(xhci, addr);
-	xhci_dbg(xhci, "  %p: ir_set.erst_size = 0x%x\n", addr,
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set.erst_size = 0x%x\n", addr,
 			(unsigned int)temp);
 
 	addr = &ir_set->rsvd;
 	temp = xhci_readl(xhci, addr);
 	if (temp != XHCI_INIT_VALUE)
-		xhci_dbg(xhci, "  WARN: %p: ir_set.rsvd = 0x%x\n",
+		xhci_dbg(xhci, XHCI_LOG_REGS,
+				"  WARN: %p: ir_set.rsvd = 0x%x\n",
 				addr, (unsigned int)temp);
 
 	addr = &ir_set->erst_base;
 	temp_64 = xhci_read_64(xhci, addr);
-	xhci_dbg(xhci, "  %p: ir_set.erst_base = @%08llx\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set.erst_base = @%08llx\n",
 			addr, temp_64);
 
 	addr = &ir_set->erst_dequeue;
 	temp_64 = xhci_read_64(xhci, addr);
-	xhci_dbg(xhci, "  %p: ir_set.erst_dequeue = @%08llx\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: ir_set.erst_dequeue = @%08llx\n",
 			addr, temp_64);
 }
 
@@ -217,15 +262,18 @@ void xhci_print_run_regs(struct xhci_hcd *xhci)
 	u32 temp;
 	int i;
 
-	xhci_dbg(xhci, "xHCI runtime registers at %p:\n", xhci->run_regs);
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"xHCI runtime registers at %p:\n", xhci->run_regs);
 	temp = xhci_readl(xhci, &xhci->run_regs->microframe_index);
-	xhci_dbg(xhci, "  %p: Microframe index = 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_REGS,
+			"  %p: Microframe index = 0x%x\n",
 			&xhci->run_regs->microframe_index,
 			(unsigned int) temp);
 	for (i = 0; i < 7; ++i) {
 		temp = xhci_readl(xhci, &xhci->run_regs->rsvd[i]);
 		if (temp != XHCI_INIT_VALUE)
-			xhci_dbg(xhci, "  WARN: %p: Rsvd[%i] = 0x%x\n",
+			xhci_dbg(xhci, XHCI_LOG_REGS,
+					"  WARN: %p: Rsvd[%i] = 0x%x\n",
 					&xhci->run_regs->rsvd[i],
 					i, (unsigned int) temp);
 	}
@@ -242,7 +290,8 @@ void xhci_print_trb_offsets(struct xhci_hcd *xhci, union xhci_trb *trb)
 {
 	int i;
 	for (i = 0; i < 4; ++i)
-		xhci_dbg(xhci, "Offset 0x%x = 0x%x\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Offset 0x%x = 0x%x\n",
 				i*4, trb->generic.field[i]);
 }
 
@@ -253,22 +302,30 @@ void xhci_debug_trb(struct xhci_hcd *xhci, union xhci_trb *trb)
 {
 	u64	address;
 	u32	type = xhci_readl(xhci, &trb->link.control) & TRB_TYPE_BITMASK;
+	unsigned int temp;
 
 	switch (type) {
 	case TRB_TYPE(TRB_LINK):
-		xhci_dbg(xhci, "Link TRB:\n");
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Link TRB:\n");
 		xhci_print_trb_offsets(xhci, trb);
 
 		address = trb->link.segment_ptr;
-		xhci_dbg(xhci, "Next ring segment DMA address = 0x%llx\n", address);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Next ring segment DMA address = 0x%llx\n",
+				address);
 
-		xhci_dbg(xhci, "Interrupter target = 0x%x\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Interrupter target = 0x%x\n",
 				GET_INTR_TARGET(trb->link.intr_target));
-		xhci_dbg(xhci, "Cycle bit = %u\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Cycle bit = %u\n",
 				(unsigned int) (trb->link.control & TRB_CYCLE));
-		xhci_dbg(xhci, "Toggle cycle bit = %u\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Toggle cycle bit = %u\n",
 				(unsigned int) (trb->link.control & LINK_TOGGLE));
-		xhci_dbg(xhci, "No Snoop bit = %u\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"No Snoop bit = %u\n",
 				(unsigned int) (trb->link.control & TRB_NO_SNOOP));
 		break;
 	case TRB_TYPE(TRB_TRANSFER):
@@ -277,17 +334,24 @@ void xhci_debug_trb(struct xhci_hcd *xhci, union xhci_trb *trb)
 		 * FIXME: look at flags to figure out if it's an address or if
 		 * the data is directly in the buffer field.
 		 */
-		xhci_dbg(xhci, "DMA address or buffer contents= %llu\n", address);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"DMA address or buffer contents= %llu\n",
+				address);
 		break;
 	case TRB_TYPE(TRB_COMPLETION):
 		address = trb->event_cmd.cmd_trb;
-		xhci_dbg(xhci, "Command TRB pointer = %llu\n", address);
-		xhci_dbg(xhci, "Completion status = %u\n",
-				(unsigned int) GET_COMP_CODE(trb->event_cmd.status));
-		xhci_dbg(xhci, "Flags = 0x%x\n", (unsigned int) trb->event_cmd.flags);
+		temp = GET_COMP_CODE(trb->event_cmd.status);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Command TRB pointer = %llu\n", address);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Completion status = %u\n", temp);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Flags = 0x%x\n",
+				(unsigned int) trb->event_cmd.flags);
 		break;
 	default:
-		xhci_dbg(xhci, "Unknown TRB with TRB type ID %u\n",
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_TX_VERBOSE),
+				"Unknown TRB with TRB type ID %u\n",
 				(unsigned int) type>>10);
 		xhci_print_trb_offsets(xhci, trb);
 		break;
@@ -315,7 +379,8 @@ void xhci_debug_segment(struct xhci_hcd *xhci, struct xhci_segment *seg)
 
 	for (i = 0; i < TRBS_PER_SEGMENT; ++i) {
 		trb = &seg->trbs[i];
-		xhci_dbg(xhci, "@%08x %08x %08x %08x %08x\n", addr,
+		xhci_dbg(xhci, XHCI_LOG_RINGS, "@%08x %08x %08x %08x %08x\n",
+				addr,
 				lower_32_bits(trb->link.segment_ptr),
 				upper_32_bits(trb->link.segment_ptr),
 				(unsigned int) trb->link.intr_target,
@@ -326,17 +391,17 @@ void xhci_debug_segment(struct xhci_hcd *xhci, struct xhci_segment *seg)
 
 void xhci_dbg_ring_ptrs(struct xhci_hcd *xhci, struct xhci_ring *ring)
 {
-	xhci_dbg(xhci, "Ring deq = %p (virt), 0x%llx (dma)\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Ring deq = %p (virt), 0x%llx (dma)\n",
 			ring->dequeue,
 			(unsigned long long)xhci_trb_virt_to_dma(ring->deq_seg,
 							    ring->dequeue));
-	xhci_dbg(xhci, "Ring deq updated %u times\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Ring deq updated %u times\n",
 			ring->deq_updates);
-	xhci_dbg(xhci, "Ring enq = %p (virt), 0x%llx (dma)\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Ring enq = %p (virt), 0x%llx (dma)\n",
 			ring->enqueue,
 			(unsigned long long)xhci_trb_virt_to_dma(ring->enq_seg,
 							    ring->enqueue));
-	xhci_dbg(xhci, "Ring enq updated %u times\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Ring enq updated %u times\n",
 			ring->enq_updates);
 }
 
@@ -357,7 +422,8 @@ void xhci_debug_ring(struct xhci_hcd *xhci, struct xhci_ring *ring)
 	xhci_debug_segment(xhci, first_seg);
 
 	if (!ring->enq_updates && !ring->deq_updates) {
-		xhci_dbg(xhci, "  Ring has not been updated\n");
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"  Ring has not been updated\n");
 		return;
 	}
 	for (seg = first_seg->next; seg != first_seg; seg = seg->next)
@@ -372,7 +438,8 @@ void xhci_dbg_erst(struct xhci_hcd *xhci, struct xhci_erst *erst)
 
 	for (i = 0; i < erst->num_entries; ++i) {
 		entry = &erst->entries[i];
-		xhci_dbg(xhci, "@%08x %08x %08x %08x %08x\n",
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"@%08x %08x %08x %08x %08x\n",
 				(unsigned int) addr,
 				lower_32_bits(entry->seg_addr),
 				upper_32_bits(entry->seg_addr),
@@ -387,21 +454,25 @@ void xhci_dbg_cmd_ptrs(struct xhci_hcd *xhci)
 	u64 val;
 
 	val = xhci_read_64(xhci, &xhci->op_regs->cmd_ring);
-	xhci_dbg(xhci, "// xHC command ring deq ptr low bits + flags = @%08x\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS,
+			"xHC command ring deq ptr low bits + flags = @%08x\n",
 			lower_32_bits(val));
-	xhci_dbg(xhci, "// xHC command ring deq ptr high bits = @%08x\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS,
+			"xHC command ring deq ptr high bits = @%08x\n",
 			upper_32_bits(val));
 }
 
 /* Print the last 32 bytes for 64-byte contexts */
-static void dbg_rsvd64(struct xhci_hcd *xhci, u64 *ctx, dma_addr_t dma)
+static void dbg_rsvd64(struct xhci_hcd *xhci, u64 *ctx, dma_addr_t dma,
+		int log_level)
 {
 	int i;
 	for (i = 0; i < 4; ++i) {
-		xhci_dbg(xhci, "@%p (virt) @%08llx "
-			 "(dma) %#08llx - rsvd64[%d]\n",
-			 &ctx[4 + i], (unsigned long long)dma,
-			 ctx[4 + i], i);
+		xhci_dbg(xhci, log_level,
+				"@%p (virt) @%08llx "
+				"(dma) %#08llx - rsvd64[%d]\n",
+				&ctx[4 + i], (unsigned long long)dma,
+				ctx[4 + i], i);
 		dma += 8;
 	}
 }
@@ -417,32 +488,37 @@ void xhci_dbg_slot_ctx(struct xhci_hcd *xhci, struct xhci_container_ctx *ctx)
 		((unsigned long)slot_ctx - (unsigned long)ctx->bytes);
 	int csz = HCC_64BYTE_CONTEXT(xhci->hcc_params);
 
-	xhci_dbg(xhci, "Slot Context:\n");
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_info\n",
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE, "Slot Context:\n");
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+			"@%p (virt) @%08llx (dma) %#08x - dev_info\n",
 			&slot_ctx->dev_info,
 			(unsigned long long)dma, slot_ctx->dev_info);
 	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_info2\n",
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+			"@%p (virt) @%08llx (dma) %#08x - dev_info2\n",
 			&slot_ctx->dev_info2,
 			(unsigned long long)dma, slot_ctx->dev_info2);
 	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - tt_info\n",
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+			"@%p (virt) @%08llx (dma) %#08x - tt_info\n",
 			&slot_ctx->tt_info,
 			(unsigned long long)dma, slot_ctx->tt_info);
 	dma += field_size;
-	xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - dev_state\n",
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+			"@%p (virt) @%08llx (dma) %#08x - dev_state\n",
 			&slot_ctx->dev_state,
 			(unsigned long long)dma, slot_ctx->dev_state);
 	dma += field_size;
 	for (i = 0; i < 4; ++i) {
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd[%d]\n",
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"@%p (virt) @%08llx (dma) %#08x - rsvd[%d]\n",
 				&slot_ctx->reserved[i], (unsigned long long)dma,
 				slot_ctx->reserved[i], i);
 		dma += field_size;
 	}
 
 	if (csz)
-		dbg_rsvd64(xhci, (u64 *)slot_ctx, dma);
+		dbg_rsvd64(xhci, (u64 *)slot_ctx, dma, XHCI_LOG_DEVICE_STATE);
 }
 
 void xhci_dbg_ep_ctx(struct xhci_hcd *xhci,
@@ -462,25 +538,32 @@ void xhci_dbg_ep_ctx(struct xhci_hcd *xhci,
 		dma_addr_t dma = ctx->dma +
 			((unsigned long)ep_ctx - (unsigned long)ctx->bytes);
 
-		xhci_dbg(xhci, "Endpoint %02d Context:\n", i);
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - ep_info\n",
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"Endpoint %02d Context:\n", i);
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"@%p (virt) @%08llx (dma) %#08x - ep_info\n",
 				&ep_ctx->ep_info,
 				(unsigned long long)dma, ep_ctx->ep_info);
 		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - ep_info2\n",
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"@%p (virt) @%08llx (dma) %#08x - ep_info2\n",
 				&ep_ctx->ep_info2,
 				(unsigned long long)dma, ep_ctx->ep_info2);
 		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08llx - deq\n",
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"@%p (virt) @%08llx (dma) %#08llx - deq\n",
 				&ep_ctx->deq,
 				(unsigned long long)dma, ep_ctx->deq);
 		dma += 2*field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - tx_info\n",
+		xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+				"@%p (virt) @%08llx (dma) %#08x - tx_info\n",
 				&ep_ctx->tx_info,
 				(unsigned long long)dma, ep_ctx->tx_info);
 		dma += field_size;
 		for (j = 0; j < 3; ++j) {
-			xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd[%d]\n",
+			xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+					"@%p (virt) @%08llx (dma) %#08x "
+					"- rsvd[%d]\n",
 					&ep_ctx->reserved[j],
 					(unsigned long long)dma,
 					ep_ctx->reserved[j], j);
@@ -488,7 +571,8 @@ void xhci_dbg_ep_ctx(struct xhci_hcd *xhci,
 		}
 
 		if (csz)
-			dbg_rsvd64(xhci, (u64 *)ep_ctx, dma);
+			dbg_rsvd64(xhci, (u64 *)ep_ctx, dma,
+					XHCI_LOG_DEVICE_STATE);
 	}
 }
 
@@ -506,23 +590,29 @@ void xhci_dbg_ctx(struct xhci_hcd *xhci,
 	if (ctx->type == XHCI_CTX_TYPE_INPUT) {
 		struct xhci_input_control_ctx *ctrl_ctx =
 			xhci_get_input_control_ctx(xhci, ctx);
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - drop flags\n",
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"@%p (virt) @%08llx (dma) %#08x - drop flags\n",
 			 &ctrl_ctx->drop_flags, (unsigned long long)dma,
 			 ctrl_ctx->drop_flags);
 		dma += field_size;
-		xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - add flags\n",
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"@%p (virt) @%08llx (dma) %#08x - add flags\n",
 			 &ctrl_ctx->add_flags, (unsigned long long)dma,
 			 ctrl_ctx->add_flags);
 		dma += field_size;
 		for (i = 0; i < 6; ++i) {
-			xhci_dbg(xhci, "@%p (virt) @%08llx (dma) %#08x - rsvd2[%d]\n",
-				 &ctrl_ctx->rsvd2[i], (unsigned long long)dma,
-				 ctrl_ctx->rsvd2[i], i);
+			xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+					"@%p (virt) @%08llx (dma) %#08x"
+					" - rsvd2[%d]\n",
+					&ctrl_ctx->rsvd2[i],
+					(unsigned long long)dma,
+					ctrl_ctx->rsvd2[i], i);
 			dma += field_size;
 		}
 
 		if (csz)
-			dbg_rsvd64(xhci, (u64 *)ctrl_ctx, dma);
+			dbg_rsvd64(xhci, (u64 *)ctrl_ctx, dma,
+					XHCI_LOG_COMMANDS_VERBOSE);
 	}
 
 	slot_ctx = xhci_get_slot_ctx(xhci, ctx);
diff --git a/drivers/usb/host/xhci-hcd.c b/drivers/usb/host/xhci-hcd.c
index 932f999..d8abbba 100644
--- a/drivers/usb/host/xhci-hcd.c
+++ b/drivers/usb/host/xhci-hcd.c
@@ -34,6 +34,11 @@ static int link_quirk;
 module_param(link_quirk, int, S_IRUGO | S_IWUSR);
 MODULE_PARM_DESC(link_quirk, "Don't clear the chain bit on a link TRB");
 
+/* Logging level bitmask, see xhci.h */
+static int log_level;
+module_param(log_level, int, S_IRUGO | S_IWUSR);
+MODULE_PARM_DESC(log_level, "Log level bitmask");
+
 /* TODO: copied from ehci-hcd.c - can this be refactored? */
 /*
  * handshake - spin reading hc until handshake completes or fails
@@ -81,7 +86,7 @@ int xhci_halt(struct xhci_hcd *xhci)
 	u32 cmd;
 	u32 mask;
 
-	xhci_dbg(xhci, "// Halt the HC\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS, "Halt the HC\n");
 	/* Disable all interrupts from the host controller */
 	mask = ~(XHCI_IRQS);
 	halted = xhci_readl(xhci, &xhci->op_regs->status) & STS_HALT;
@@ -114,7 +119,7 @@ int xhci_reset(struct xhci_hcd *xhci)
 		return 0;
 	}
 
-	xhci_dbg(xhci, "// Reset the HC\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS, "Reset the HC\n");
 	command = xhci_readl(xhci, &xhci->op_regs->command);
 	command |= CMD_RESET;
 	xhci_writel(xhci, command, &xhci->op_regs->command);
@@ -144,7 +149,6 @@ static void xhci_quiesce(struct xhci_hcd *xhci)
 	 * TODO: Implement after command ring code is done.
 	 */
 	BUG_ON(!HC_IS_RUNNING(xhci_to_hcd(xhci)->state));
-	xhci_dbg(xhci, "Finished quiescing -- code not written yet\n");
 }
 
 #if 0
@@ -179,7 +183,7 @@ static int xhci_setup_msix(struct xhci_hcd *xhci)
 		xhci_err(xhci, "Failed to allocate MSI-X interrupt\n");
 		goto disable_msix;
 	}
-	xhci_dbg(xhci, "Finished setting up MSI-X\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Finished setting up MSI-X\n");
 	return 0;
 
 disable_msix:
@@ -202,7 +206,7 @@ static void xhci_cleanup_msix(struct xhci_hcd *xhci)
 	pci_disable_msix(pdev);
 	kfree(xhci->msix_entries);
 	xhci->msix_entries = NULL;
-	xhci_dbg(xhci, "Finished cleaning up MSI-X\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Finished cleaning up MSI-X\n");
 }
 #endif
 
@@ -218,16 +222,19 @@ int xhci_init(struct usb_hcd *hcd)
 	struct xhci_hcd *xhci = hcd_to_xhci(hcd);
 	int retval = 0;
 
-	xhci_dbg(xhci, "xhci_init\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "xhci_init\n");
 	spin_lock_init(&xhci->lock);
 	if (link_quirk) {
-		xhci_dbg(xhci, "QUIRK: Not clearing Link TRB chain bits.\n");
+		xhci_dbg(xhci, XHCI_LOG_QUIRKS,
+				"QUIRK: Not clearing Link TRB chain bits.\n");
 		xhci->quirks |= XHCI_LINK_TRB_QUIRK;
 	} else {
-		xhci_dbg(xhci, "xHCI doesn't need link TRB QUIRK\n");
+		xhci_dbg(xhci, XHCI_LOG_QUIRKS,
+				"xHCI doesn't need link TRB QUIRK\n");
 	}
+	xhci->log_level = log_level;
 	retval = xhci_mem_init(xhci, GFP_KERNEL);
-	xhci_dbg(xhci, "Finished xhci_init\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Finished xhci_init\n");
 
 	return retval;
 }
@@ -296,10 +303,9 @@ irqreturn_t xhci_irq(struct usb_hcd *hcd)
 		spin_unlock(&xhci->lock);
 		return IRQ_NONE;
 	}
-	xhci_dbg(xhci, "op reg status = %08x\n", temp);
-	xhci_dbg(xhci, "ir set irq_pending = %08x\n", temp2);
-	xhci_dbg(xhci, "Event ring dequeue ptr:\n");
-	xhci_dbg(xhci, "@%llx %08x %08x %08x %08x\n",
+	xhci_dbg(xhci, XHCI_LOG_EVENTS,
+			"xHCI IRQ -- event ring dequeue ptr:\n");
+	xhci_dbg(xhci, XHCI_LOG_EVENTS, "@%llx %08x %08x %08x %08x\n",
 			(unsigned long long)xhci_trb_virt_to_dma(xhci->event_ring->deq_seg, trb),
 			lower_32_bits(trb->link.segment_ptr),
 			upper_32_bits(trb->link.segment_ptr),
@@ -330,29 +336,33 @@ void xhci_event_ring_work(unsigned long arg)
 	struct xhci_hcd *xhci = (struct xhci_hcd *) arg;
 	int i, j;
 
-	xhci_dbg(xhci, "Poll event ring: %lu\n", jiffies);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Poll event ring: %lu\n", jiffies);
 
 	spin_lock_irqsave(&xhci->lock, flags);
 	temp = xhci_readl(xhci, &xhci->op_regs->status);
-	xhci_dbg(xhci, "op reg status = 0x%x\n", temp);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "op reg status = 0x%x\n", temp);
 	if (temp == 0xffffffff) {
-		xhci_dbg(xhci, "HW died, polling stopped.\n");
+		xhci_warn(xhci, "HW died, polling stopped.\n");
 		spin_unlock_irqrestore(&xhci->lock, flags);
 		return;
 	}
 
 	temp = xhci_readl(xhci, &xhci->ir_set->irq_pending);
-	xhci_dbg(xhci, "ir_set 0 pending = 0x%x\n", temp);
-	xhci_dbg(xhci, "No-op commands handled = %d\n", xhci->noops_handled);
-	xhci_dbg(xhci, "HC error bitmask = 0x%x\n", xhci->error_bitmask);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "ir_set 0 pending = 0x%x\n", temp);
+	xhci_dbg(xhci, XHCI_LOG_NOOPS, "No-op commands handled = %d\n",
+			xhci->noops_handled);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "HC error bitmask = 0x%x\n",
+			xhci->error_bitmask);
+
 	xhci->error_bitmask = 0;
-	xhci_dbg(xhci, "Event ring:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Event ring:\n");
 	xhci_debug_segment(xhci, xhci->event_ring->deq_seg);
 	xhci_dbg_ring_ptrs(xhci, xhci->event_ring);
 	temp_64 = xhci_read_64(xhci, &xhci->ir_set->erst_dequeue);
 	temp_64 &= ~ERST_PTR_MASK;
-	xhci_dbg(xhci, "ERST deq = 64'h%0lx\n", (long unsigned int) temp_64);
-	xhci_dbg(xhci, "Command ring:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "ERST deq = 64'h%0lx\n",
+			(long unsigned int) temp_64);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Command ring:\n");
 	xhci_debug_segment(xhci, xhci->cmd_ring->deq_seg);
 	xhci_dbg_ring_ptrs(xhci, xhci->cmd_ring);
 	xhci_dbg_cmd_ptrs(xhci);
@@ -363,7 +373,14 @@ void xhci_event_ring_work(unsigned long arg)
 			struct xhci_ring *ring = xhci->devs[i]->eps[j].ring;
 			if (!ring)
 				continue;
-			xhci_dbg(xhci, "Dev %d endpoint ring %d:\n", i, j);
+			if (!ring->enq_updates && !ring->deq_updates) {
+				xhci_dbg(xhci, XHCI_LOG_RINGS,
+						"Dev %d endpoint ring %d "
+						"is unused:\n", i, j);
+				continue;
+			}
+			xhci_dbg(xhci, XHCI_LOG_RINGS,
+					"Dev %d endpoint ring %d:\n", i, j);
 			xhci_debug_segment(xhci, ring->deq_seg);
 		}
 	}
@@ -375,8 +392,6 @@ void xhci_event_ring_work(unsigned long arg)
 
 	if (!xhci->zombie)
 		mod_timer(&xhci->event_ring_timer, jiffies + POLL_TIMEOUT * HZ);
-	else
-		xhci_dbg(xhci, "Quit polling the event ring.\n");
 }
 #endif
 
@@ -402,7 +417,6 @@ int xhci_run(struct usb_hcd *hcd)
 	hcd->uses_new_polling = 1;
 	hcd->poll_rh = 0;
 
-	xhci_dbg(xhci, "xhci_run\n");
 #if 0	/* FIXME: MSI not setup yet */
 	/* Do this at the very last minute */
 	ret = xhci_setup_msix(xhci);
@@ -418,25 +432,25 @@ int xhci_run(struct usb_hcd *hcd)
 	/* Poll the event ring */
 	xhci->event_ring_timer.expires = jiffies + POLL_TIMEOUT * HZ;
 	xhci->zombie = 0;
-	xhci_dbg(xhci, "Setting event ring polling timer\n");
 	add_timer(&xhci->event_ring_timer);
 #endif
 
-	xhci_dbg(xhci, "Command ring memory map follows:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Command ring memory map follows:\n");
 	xhci_debug_ring(xhci, xhci->cmd_ring);
 	xhci_dbg_ring_ptrs(xhci, xhci->cmd_ring);
 	xhci_dbg_cmd_ptrs(xhci);
 
-	xhci_dbg(xhci, "ERST memory map follows:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "ERST memory map follows:\n");
 	xhci_dbg_erst(xhci, &xhci->erst);
-	xhci_dbg(xhci, "Event ring:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Event ring:\n");
 	xhci_debug_ring(xhci, xhci->event_ring);
 	xhci_dbg_ring_ptrs(xhci, xhci->event_ring);
 	temp_64 = xhci_read_64(xhci, &xhci->ir_set->erst_dequeue);
 	temp_64 &= ~ERST_PTR_MASK;
-	xhci_dbg(xhci, "ERST deq = 64'h%0lx\n", (long unsigned int) temp_64);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "ERST deq = 64'h%0lx\n",
+			(long unsigned int) temp_64);
 
-	xhci_dbg(xhci, "// Set the interrupt modulation register\n");
+	/* Set the interrupt modulation register */
 	temp = xhci_readl(xhci, &xhci->ir_set->irq_control);
 	temp &= ~ER_IRQ_INTERVAL_MASK;
 	temp |= (u32) 160;
@@ -446,13 +460,9 @@ int xhci_run(struct usb_hcd *hcd)
 	hcd->state = HC_STATE_RUNNING;
 	temp = xhci_readl(xhci, &xhci->op_regs->command);
 	temp |= (CMD_EIE);
-	xhci_dbg(xhci, "// Enable interrupts, cmd = 0x%x.\n",
-			temp);
 	xhci_writel(xhci, temp, &xhci->op_regs->command);
 
 	temp = xhci_readl(xhci, &xhci->ir_set->irq_pending);
-	xhci_dbg(xhci, "// Enabling event ring interrupter %p by writing 0x%x to irq_pending\n",
-			xhci->ir_set, (unsigned int) ER_IRQ_ENABLE(temp));
 	xhci_writel(xhci, ER_IRQ_ENABLE(temp),
 			&xhci->ir_set->irq_pending);
 	xhci_print_ir_set(xhci, xhci->ir_set, 0);
@@ -462,16 +472,14 @@ int xhci_run(struct usb_hcd *hcd)
 
 	temp = xhci_readl(xhci, &xhci->op_regs->command);
 	temp |= (CMD_RUN);
-	xhci_dbg(xhci, "// Turn on HC, cmd = 0x%x.\n",
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Turn on HC, cmd = 0x%x.\n",
 			temp);
 	xhci_writel(xhci, temp, &xhci->op_regs->command);
 	/* Flush PCI posted writes */
 	temp = xhci_readl(xhci, &xhci->op_regs->command);
-	xhci_dbg(xhci, "// @%p = 0x%x\n", &xhci->op_regs->command, temp);
 	if (doorbell)
 		(*doorbell)(xhci);
 
-	xhci_dbg(xhci, "Finished xhci_run\n");
 	return 0;
 }
 
@@ -505,7 +513,6 @@ void xhci_stop(struct usb_hcd *hcd)
 	del_timer_sync(&xhci->event_ring_timer);
 #endif
 
-	xhci_dbg(xhci, "// Disabling event ring interrupts\n");
 	temp = xhci_readl(xhci, &xhci->op_regs->status);
 	xhci_writel(xhci, temp & ~STS_EINT, &xhci->op_regs->status);
 	temp = xhci_readl(xhci, &xhci->ir_set->irq_pending);
@@ -513,9 +520,8 @@ void xhci_stop(struct usb_hcd *hcd)
 			&xhci->ir_set->irq_pending);
 	xhci_print_ir_set(xhci, xhci->ir_set, 0);
 
-	xhci_dbg(xhci, "cleaning up memory\n");
 	xhci_mem_cleanup(xhci);
-	xhci_dbg(xhci, "xhci_stop completed - status = %x\n",
+	xhci_dbg(xhci, XHCI_LOG_INIT, "xhci_stop completed - status = %x\n",
 		    xhci_readl(xhci, &xhci->op_regs->status));
 }
 
@@ -538,7 +544,7 @@ void xhci_shutdown(struct usb_hcd *hcd)
 	xhci_cleanup_msix(xhci);
 #endif
 
-	xhci_dbg(xhci, "xhci_shutdown completed - status = %x\n",
+	xhci_dbg(xhci, XHCI_LOG_INIT, "xhci_shutdown completed - status = %x\n",
 		    xhci_readl(xhci, &xhci->op_regs->status));
 }
 
@@ -599,21 +605,12 @@ unsigned int xhci_last_valid_endpoint(u32 added_ctxs)
  */
 int xhci_check_args(struct usb_hcd *hcd, struct usb_device *udev,
 		struct usb_host_endpoint *ep, int check_ep, const char *func) {
-	if (!hcd || (check_ep && !ep) || !udev) {
-		printk(KERN_DEBUG "xHCI %s called with invalid args\n",
-				func);
+	if (!hcd || (check_ep && !ep) || !udev)
 		return -EINVAL;
-	}
-	if (!udev->parent) {
-		printk(KERN_DEBUG "xHCI %s called for root hub\n",
-				func);
+	if (!udev->parent)
 		return 0;
-	}
-	if (!udev->slot_id) {
-		printk(KERN_DEBUG "xHCI %s called with unaddressed device\n",
-				func);
+	if (!udev->slot_id)
 		return -EINVAL;
-	}
 	return 1;
 }
 
@@ -643,12 +640,16 @@ static int xhci_check_maxpacket(struct xhci_hcd *xhci, unsigned int slot_id,
 	hw_max_packet_size = MAX_PACKET_DECODED(ep_ctx->ep_info2);
 	max_packet_size = urb->dev->ep0.desc.wMaxPacketSize;
 	if (hw_max_packet_size != max_packet_size) {
-		xhci_dbg(xhci, "Max Packet Size for ep 0 changed.\n");
-		xhci_dbg(xhci, "Max packet size in usb_device = %d\n",
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Max Packet Size for ep 0 changed.\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Max packet size in usb_device = %d\n",
 				max_packet_size);
-		xhci_dbg(xhci, "Max packet size in xHCI HW = %d\n",
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Max packet size in xHCI HW = %d\n",
 				hw_max_packet_size);
-		xhci_dbg(xhci, "Issuing evaluate context command.\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Issuing evaluate context command.\n");
 
 		/* Set up the modified control endpoint 0 */
 		xhci_endpoint_copy(xhci, xhci->devs[slot_id]->in_ctx,
@@ -666,9 +667,11 @@ static int xhci_check_maxpacket(struct xhci_hcd *xhci, unsigned int slot_id,
 		ctrl_ctx->add_flags = EP0_FLAG;
 		ctrl_ctx->drop_flags = 0;
 
-		xhci_dbg(xhci, "Slot %d input context\n", slot_id);
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"Slot %d input context\n", slot_id);
 		xhci_dbg_ctx(xhci, in_ctx, ep_index);
-		xhci_dbg(xhci, "Slot %d output context\n", slot_id);
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"Slot %d output context\n", slot_id);
 		xhci_dbg_ctx(xhci, out_ctx, ep_index);
 
 		ret = xhci_configure_endpoint(xhci, urb->dev, NULL,
@@ -701,14 +704,14 @@ int xhci_urb_enqueue(struct usb_hcd *hcd, struct urb *urb, gfp_t mem_flags)
 	ep_index = xhci_get_endpoint_index(&urb->ep->desc);
 
 	if (!xhci->devs || !xhci->devs[slot_id]) {
-		if (!in_interrupt())
-			dev_warn(&urb->dev->dev, "WARN: urb submitted for dev with no Slot ID\n");
+		xhci_warn(xhci, "WARN: urb submitted for dev "
+				"with no Slot ID\n");
 		ret = -EINVAL;
 		goto exit;
 	}
 	if (!test_bit(HCD_FLAG_HW_ACCESSIBLE, &hcd->flags)) {
-		if (!in_interrupt())
-			xhci_dbg(xhci, "urb submitted during PCI suspend\n");
+		xhci_dbg(xhci, XHCI_LOG_TX,
+				"urb submitted during PCI suspend\n");
 		ret = -ESHUTDOWN;
 		goto exit;
 	}
@@ -797,7 +800,7 @@ int xhci_urb_dequeue(struct usb_hcd *hcd, struct urb *urb, int status)
 		goto done;
 	temp = xhci_readl(xhci, &xhci->op_regs->status);
 	if (temp == 0xffffffff) {
-		xhci_dbg(xhci, "HW died, freeing TD.\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "HW died, freeing TD.\n");
 		td = (struct xhci_td *) urb->hcpriv;
 
 		usb_hcd_unlink_urb_from_ep(hcd, urb);
@@ -807,13 +810,13 @@ int xhci_urb_dequeue(struct usb_hcd *hcd, struct urb *urb, int status)
 		return ret;
 	}
 
-	xhci_dbg(xhci, "Cancel URB %p\n", urb);
-	xhci_dbg(xhci, "Event ring:\n");
+	xhci_dbg(xhci, XHCI_LOG_TX, "Cancel URB %p\n", urb);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Event ring:\n");
 	xhci_debug_ring(xhci, xhci->event_ring);
 	ep_index = xhci_get_endpoint_index(&urb->ep->desc);
 	ep = &xhci->devs[urb->dev->slot_id]->eps[ep_index];
 	ep_ring = ep->ring;
-	xhci_dbg(xhci, "Endpoint ring:\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Endpoint ring:\n");
 	xhci_debug_ring(xhci, ep_ring);
 	td = (struct xhci_td *) urb->hcpriv;
 
@@ -862,12 +865,11 @@ int xhci_drop_endpoint(struct usb_hcd *hcd, struct usb_device *udev,
 	if (ret <= 0)
 		return ret;
 	xhci = hcd_to_xhci(hcd);
-	xhci_dbg(xhci, "%s called for udev %p\n", __func__, udev);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"%s called for udev %p\n", __func__, udev);
 
 	drop_flag = xhci_get_endpoint_flag(&ep->desc);
 	if (drop_flag == SLOT_FLAG || drop_flag == EP0_FLAG) {
-		xhci_dbg(xhci, "xHCI %s - can't drop slot or ep 0 %#x\n",
-				__func__, drop_flag);
 		return 0;
 	}
 
@@ -909,7 +911,9 @@ int xhci_drop_endpoint(struct usb_hcd *hcd, struct usb_device *udev,
 
 	xhci_endpoint_zero(xhci, xhci->devs[udev->slot_id], ep);
 
-	xhci_dbg(xhci, "drop ep 0x%x, slot id %d, new drop flags = %#x, new add flags = %#x, new slot info = %#x\n",
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"drop ep 0x%x, slot id %d, new drop flags = %#x, "
+			"new add flags = %#x, new slot info = %#x\n",
 			(unsigned int) ep->desc.bEndpointAddress,
 			udev->slot_id,
 			(unsigned int) new_drop_flags,
@@ -956,12 +960,6 @@ int xhci_add_endpoint(struct usb_hcd *hcd, struct usb_device *udev,
 	added_ctxs = xhci_get_endpoint_flag(&ep->desc);
 	last_ctx = xhci_last_valid_endpoint(added_ctxs);
 	if (added_ctxs == SLOT_FLAG || added_ctxs == EP0_FLAG) {
-		/* FIXME when we have to issue an evaluate endpoint command to
-		 * deal with ep0 max packet size changing once we get the
-		 * descriptors
-		 */
-		xhci_dbg(xhci, "xHCI %s - can't add slot or ep 0 %#x\n",
-				__func__, added_ctxs);
 		return 0;
 	}
 
@@ -992,7 +990,7 @@ int xhci_add_endpoint(struct usb_hcd *hcd, struct usb_device *udev,
 	 */
 	if (xhci_endpoint_init(xhci, xhci->devs[udev->slot_id],
 				udev, ep, GFP_KERNEL) < 0) {
-		dev_dbg(&udev->dev, "%s - could not initialize ep %#x\n",
+		xhci_warn(xhci, "%s - could not initialize ep %#x\n",
 				__func__, ep->desc.bEndpointAddress);
 		return -ENOMEM;
 	}
@@ -1019,7 +1017,9 @@ int xhci_add_endpoint(struct usb_hcd *hcd, struct usb_device *udev,
 	/* Store the usb_device pointer for later use */
 	ep->hcpriv = udev;
 
-	xhci_dbg(xhci, "add ep 0x%x, slot id %d, new drop flags = %#x, new add flags = %#x, new slot info = %#x\n",
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"add ep 0x%x, slot id %d, new drop flags = %#x, "
+			"new add flags = %#x, new slot info = %#x\n",
 			(unsigned int) ep->desc.bEndpointAddress,
 			udev->slot_id,
 			(unsigned int) new_drop_flags,
@@ -1063,26 +1063,27 @@ static int xhci_configure_endpoint_result(struct xhci_hcd *xhci,
 
 	switch (*cmd_status) {
 	case COMP_ENOMEM:
-		dev_warn(&udev->dev, "Not enough host controller resources "
+		xhci_warn(xhci, "Not enough host controller resources "
 				"for new device state.\n");
 		ret = -ENOMEM;
 		/* FIXME: can we allocate more resources for the HC? */
 		break;
 	case COMP_BW_ERR:
-		dev_warn(&udev->dev, "Not enough bandwidth "
+		xhci_warn(xhci, "Not enough bandwidth "
 				"for new device state.\n");
 		ret = -ENOSPC;
 		/* FIXME: can we go back to the old state? */
 		break;
 	case COMP_TRB_ERR:
 		/* the HCD set up something wrong */
-		dev_warn(&udev->dev, "ERROR: Endpoint drop flag = 0, "
+		xhci_warn(xhci, "ERROR: Endpoint drop flag = 0, "
 				"add flag = 1, "
 				"and endpoint is not disabled.\n");
 		ret = -EINVAL;
 		break;
 	case COMP_SUCCESS:
-		dev_dbg(&udev->dev, "Successful Endpoint Configure command\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Successful Endpoint Configure command\n");
 		ret = 0;
 		break;
 	default:
@@ -1102,21 +1103,22 @@ static int xhci_evaluate_context_result(struct xhci_hcd *xhci,
 
 	switch (*cmd_status) {
 	case COMP_EINVAL:
-		dev_warn(&udev->dev, "WARN: xHCI driver setup invalid evaluate "
+		xhci_warn(xhci, "WARN: xHCI driver setup invalid evaluate "
 				"context command.\n");
 		ret = -EINVAL;
 		break;
 	case COMP_EBADSLT:
-		dev_warn(&udev->dev, "WARN: slot not enabled for"
+		xhci_warn(xhci, "WARN: slot not enabled for"
 				"evaluate context command.\n");
 	case COMP_CTX_STATE:
-		dev_warn(&udev->dev, "WARN: invalid context state for "
+		xhci_warn(xhci, "WARN: invalid context state for "
 				"evaluate context command.\n");
 		xhci_dbg_ctx(xhci, virt_dev->out_ctx, 1);
 		ret = -EINVAL;
 		break;
 	case COMP_SUCCESS:
-		dev_dbg(&udev->dev, "Successful evaluate context command\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Successful evaluate context command\n");
 		ret = 0;
 		break;
 	default:
@@ -1166,7 +1168,7 @@ static int xhci_configure_endpoint(struct xhci_hcd *xhci,
 				udev->slot_id);
 	if (ret < 0) {
 		spin_unlock_irqrestore(&xhci->lock, flags);
-		xhci_dbg(xhci, "FIXME allocate a new ring segment\n");
+		xhci_warn(xhci, "FIXME allocate a new ring segment\n");
 		return -ENOMEM;
 	}
 	xhci_ring_cmd_db(xhci);
@@ -1220,7 +1222,8 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 				__func__);
 		return -EINVAL;
 	}
-	xhci_dbg(xhci, "%s called for udev %p\n", __func__, udev);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"%s called for udev %p\n", __func__, udev);
 	virt_dev = xhci->devs[udev->slot_id];
 
 	/* See section 4.6.6 - A0 = 1; A1 = D0 = D1 = 0 */
@@ -1229,7 +1232,8 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 	ctrl_ctx->add_flags &= ~EP0_FLAG;
 	ctrl_ctx->drop_flags &= ~SLOT_FLAG;
 	ctrl_ctx->drop_flags &= ~EP0_FLAG;
-	xhci_dbg(xhci, "New Input Control Context:\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"New Input Control Context:\n");
 	slot_ctx = xhci_get_slot_ctx(xhci, virt_dev->in_ctx);
 	xhci_dbg_ctx(xhci, virt_dev->in_ctx,
 			LAST_CTX_TO_EP_NUM(slot_ctx->dev_info));
@@ -1241,7 +1245,8 @@ int xhci_check_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 		return ret;
 	}
 
-	xhci_dbg(xhci, "Output context after successful config ep cmd:\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Output context after successful config ep cmd:\n");
 	xhci_dbg_ctx(xhci, virt_dev->out_ctx,
 			LAST_CTX_TO_EP_NUM(slot_ctx->dev_info));
 
@@ -1274,7 +1279,8 @@ void xhci_reset_bandwidth(struct usb_hcd *hcd, struct usb_device *udev)
 				__func__);
 		return;
 	}
-	xhci_dbg(xhci, "%s called for udev %p\n", __func__, udev);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"%s called for udev %p\n", __func__, udev);
 	virt_dev = xhci->devs[udev->slot_id];
 	/* Free any rings allocated for added endpoints */
 	for (i = 0; i < 31; ++i) {
@@ -1298,7 +1304,7 @@ static void xhci_setup_input_ctx_for_config_ep(struct xhci_hcd *xhci,
 	xhci_slot_copy(xhci, in_ctx, out_ctx);
 	ctrl_ctx->add_flags |= SLOT_FLAG;
 
-	xhci_dbg(xhci, "Input Context:\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE, "Input Context:\n");
 	xhci_dbg_ctx(xhci, in_ctx, xhci_last_valid_endpoint(add_flags));
 }
 
@@ -1338,7 +1344,8 @@ void xhci_cleanup_stalled_ring(struct xhci_hcd *xhci,
 	struct xhci_dequeue_state deq_state;
 	struct xhci_virt_ep *ep;
 
-	xhci_dbg(xhci, "Cleaning up stalled endpoint ring\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"Cleaning up stalled endpoint ring\n");
 	ep = &xhci->devs[udev->slot_id]->eps[ep_index];
 	/* We need to move the HW's dequeue pointer past this TD,
 	 * or it will attempt to resend it on the next doorbell ring.
@@ -1351,14 +1358,16 @@ void xhci_cleanup_stalled_ring(struct xhci_hcd *xhci,
 	 * issue a configure endpoint command later.
 	 */
 	if (!(xhci->quirks & XHCI_RESET_EP_QUIRK)) {
-		xhci_dbg(xhci, "Queueing new dequeue state\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Queueing new dequeue state\n");
 		xhci_queue_new_dequeue_state(xhci, udev->slot_id,
 				ep_index, &deq_state);
 	} else {
 		/* Better hope no one uses the input context between now and the
 		 * reset endpoint completion!
 		 */
-		xhci_dbg(xhci, "Setting up input context for "
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Setting up input context for "
 				"configure endpoint command\n");
 		xhci_setup_input_ctx_for_quirk(xhci, udev->slot_id,
 				ep_index, &deq_state);
@@ -1391,16 +1400,13 @@ void xhci_endpoint_reset(struct usb_hcd *hcd,
 	ep_index = xhci_get_endpoint_index(&ep->desc);
 	virt_ep = &xhci->devs[udev->slot_id]->eps[ep_index];
 	if (!virt_ep->stopped_td) {
-		xhci_dbg(xhci, "Endpoint 0x%x not halted, refusing to reset.\n",
-				ep->desc.bEndpointAddress);
 		return;
 	}
 	if (usb_endpoint_xfer_control(&ep->desc)) {
-		xhci_dbg(xhci, "Control endpoint stall already handled.\n");
 		return;
 	}
 
-	xhci_dbg(xhci, "Queueing reset endpoint command\n");
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS, "Queueing reset endpoint command\n");
 	spin_lock_irqsave(&xhci->lock, flags);
 	ret = xhci_queue_reset_ep(xhci, udev->slot_id, ep_index);
 	/*
@@ -1444,7 +1450,7 @@ void xhci_free_dev(struct usb_hcd *hcd, struct usb_device *udev)
 
 	if (xhci_queue_slot_control(xhci, TRB_DISABLE_SLOT, udev->slot_id)) {
 		spin_unlock_irqrestore(&xhci->lock, flags);
-		xhci_dbg(xhci, "FIXME: allocate a command ring segment\n");
+		xhci_warn(xhci, "FIXME: allocate a command ring segment\n");
 		return;
 	}
 	xhci_ring_cmd_db(xhci);
@@ -1470,7 +1476,7 @@ int xhci_alloc_dev(struct usb_hcd *hcd, struct usb_device *udev)
 	ret = xhci_queue_slot_control(xhci, TRB_ENABLE_SLOT, 0);
 	if (ret) {
 		spin_unlock_irqrestore(&xhci->lock, flags);
-		xhci_dbg(xhci, "FIXME: allocate a command ring segment\n");
+		xhci_warn(xhci, "FIXME: allocate a command ring segment\n");
 		return 0;
 	}
 	xhci_ring_cmd_db(xhci);
@@ -1527,7 +1533,7 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 	u64 temp_64;
 
 	if (!udev->slot_id) {
-		xhci_dbg(xhci, "Bad Slot ID %d\n", udev->slot_id);
+		xhci_warn(xhci, "Bad Slot ID %d\n", udev->slot_id);
 		return -EINVAL;
 	}
 
@@ -1537,7 +1543,8 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 	if (!udev->config)
 		xhci_setup_addressable_virt_dev(xhci, udev);
 	/* Otherwise, assume the core has the device configured how it wants */
-	xhci_dbg(xhci, "Slot ID %d Input Context:\n", udev->slot_id);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Slot ID %d Input Context:\n", udev->slot_id);
 	xhci_dbg_ctx(xhci, virt_dev->in_ctx, 2);
 
 	spin_lock_irqsave(&xhci->lock, flags);
@@ -1545,7 +1552,7 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 					udev->slot_id);
 	if (ret) {
 		spin_unlock_irqrestore(&xhci->lock, flags);
-		xhci_dbg(xhci, "FIXME: allocate a command ring segment\n");
+		xhci_warn(xhci, "FIXME: allocate a command ring segment\n");
 		return ret;
 	}
 	xhci_ring_cmd_db(xhci);
@@ -1573,16 +1580,18 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 		ret = -EINVAL;
 		break;
 	case COMP_TX_ERR:
-		dev_warn(&udev->dev, "Device not responding to set address.\n");
+		xhci_warn(xhci, "Device not responding to set address.\n");
 		ret = -EPROTO;
 		break;
 	case COMP_SUCCESS:
-		xhci_dbg(xhci, "Successful Address Device command\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Successful Address Device command\n");
 		break;
 	default:
 		xhci_err(xhci, "ERROR: unexpected command completion "
 				"code 0x%x.\n", virt_dev->cmd_status);
-		xhci_dbg(xhci, "Slot ID %d Output Context:\n", udev->slot_id);
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"Slot ID %d Output Context:\n", udev->slot_id);
 		xhci_dbg_ctx(xhci, virt_dev->out_ctx, 2);
 		ret = -EINVAL;
 		break;
@@ -1591,17 +1600,11 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 		return ret;
 	}
 	temp_64 = xhci_read_64(xhci, &xhci->op_regs->dcbaa_ptr);
-	xhci_dbg(xhci, "Op regs DCBAA ptr = %#016llx\n", temp_64);
-	xhci_dbg(xhci, "Slot ID %d dcbaa entry @%p = %#016llx\n",
-			udev->slot_id,
-			&xhci->dcbaa->dev_context_ptrs[udev->slot_id],
-			(unsigned long long)
-				xhci->dcbaa->dev_context_ptrs[udev->slot_id]);
-	xhci_dbg(xhci, "Output Context DMA address = %#08llx\n",
-			(unsigned long long)virt_dev->out_ctx->dma);
-	xhci_dbg(xhci, "Slot ID %d Input Context:\n", udev->slot_id);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Slot ID %d Input Context:\n", udev->slot_id);
 	xhci_dbg_ctx(xhci, virt_dev->in_ctx, 2);
-	xhci_dbg(xhci, "Slot ID %d Output Context:\n", udev->slot_id);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Slot ID %d Output Context:\n", udev->slot_id);
 	xhci_dbg_ctx(xhci, virt_dev->out_ctx, 2);
 	/*
 	 * USB core uses address 1 for the roothubs, so we add one to the
@@ -1614,7 +1617,8 @@ int xhci_address_device(struct usb_hcd *hcd, struct usb_device *udev)
 	ctrl_ctx->add_flags = 0;
 	ctrl_ctx->drop_flags = 0;
 
-	xhci_dbg(xhci, "Device address = %d\n", udev->devnum);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Device address = %d\n", udev->devnum);
 	/* XXX Meh, not sure if anyone else but choose_address uses this. */
 	set_bit(udev->devnum, udev->bus->devmap.devicemap);
 
@@ -1647,7 +1651,7 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 	}
 	config_cmd = xhci_alloc_command(xhci, true, mem_flags);
 	if (!config_cmd) {
-		xhci_dbg(xhci, "Could not allocate xHCI command structure.\n");
+		xhci_warn(xhci, "Could not allocate xHCI command structure.\n");
 		return -ENOMEM;
 	}
 
@@ -1660,7 +1664,8 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 	if (tt->multi)
 		slot_ctx->dev_info |= DEV_MTT;
 	if (xhci->hci_version > 0x95) {
-		xhci_dbg(xhci, "xHCI version %x needs hub "
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"xHCI version %x needs hub "
 				"TT think time and number of ports\n",
 				(unsigned int) xhci->hci_version);
 		slot_ctx->dev_info2 |= XHCI_MAX_PORTS(hdev->maxchild);
@@ -1673,17 +1678,20 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 			think_time = (think_time / 666) - 1;
 		slot_ctx->tt_info |= TT_THINK_TIME(think_time);
 	} else {
-		xhci_dbg(xhci, "xHCI version %x doesn't need hub "
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+				"xHCI version %x doesn't need hub "
 				"TT think time or number of ports\n",
 				(unsigned int) xhci->hci_version);
 	}
 	slot_ctx->dev_state = 0;
 	spin_unlock_irqrestore(&xhci->lock, flags);
 
-	xhci_dbg(xhci, "Set up %s for hub device.\n",
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+			"Set up %s for hub device.\n",
 			(xhci->hci_version > 0x95) ?
 			"configure endpoint" : "evaluate context");
-	xhci_dbg(xhci, "Slot %u Input Context:\n", hdev->slot_id);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Slot %u Input Context:\n", hdev->slot_id);
 	xhci_dbg_ctx(xhci, config_cmd->in_ctx, 0);
 
 	/* Issue and wait for the configure endpoint or
@@ -1696,7 +1704,8 @@ int xhci_update_hub_device(struct usb_hcd *hcd, struct usb_device *hdev,
 		ret = xhci_configure_endpoint(xhci, hdev, config_cmd,
 				true, false);
 
-	xhci_dbg(xhci, "Slot %u Output Context:\n", hdev->slot_id);
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Slot %u Output Context:\n", hdev->slot_id);
 	xhci_dbg_ctx(xhci, vdev->out_ctx, 0);
 
 	xhci_free_command(xhci, config_cmd);
diff --git a/drivers/usb/host/xhci-hub.c b/drivers/usb/host/xhci-hub.c
index eac5b53..de9ed07 100644
--- a/drivers/usb/host/xhci-hub.c
+++ b/drivers/usb/host/xhci-hub.c
@@ -158,7 +158,6 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 		status = 0;
 		addr = &xhci->op_regs->port_status_base + NUM_PORT_REGS*(wIndex & 0xff);
 		temp = xhci_readl(xhci, addr);
-		xhci_dbg(xhci, "get port status, actual port %d status  = 0x%x\n", wIndex, temp);
 
 		/* wPortChange bits */
 		if (temp & PORT_CSC)
@@ -183,7 +182,10 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 			status |= 1 << USB_PORT_FEAT_RESET;
 		if (temp & PORT_POWER)
 			status |= 1 << USB_PORT_FEAT_POWER;
-		xhci_dbg(xhci, "Get port status returned 0x%x\n", status);
+		xhci_dbg(xhci, XHCI_LOG_PORTS,
+				"Get port %d status, actual status  = 0x%x, "
+				"returned status = 0x%x\n",
+				wIndex, temp, status);
 		put_unaligned(cpu_to_le32(status), (__le32 *) buf);
 		break;
 	case SetPortFeature:
@@ -205,14 +207,19 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 			xhci_writel(xhci, temp | PORT_POWER, addr);
 
 			temp = xhci_readl(xhci, addr);
-			xhci_dbg(xhci, "set port power, actual port %d status  = 0x%x\n", wIndex, temp);
+			xhci_dbg(xhci, XHCI_LOG_PORTS,
+					"Set port %d power, "
+					"actual status  = 0x%x\n",
+					wIndex, temp);
 			break;
 		case USB_PORT_FEAT_RESET:
 			temp = (temp | PORT_RESET);
 			xhci_writel(xhci, temp, addr);
 
 			temp = xhci_readl(xhci, addr);
-			xhci_dbg(xhci, "set port reset, actual port %d status  = 0x%x\n", wIndex, temp);
+			xhci_dbg(xhci, XHCI_LOG_PORTS, "Set port %d reset, "
+					"actual status  = 0x%x\n",
+					wIndex, temp);
 			break;
 		default:
 			goto error;
@@ -246,8 +253,10 @@ int xhci_hub_control(struct usb_hcd *hcd, u16 typeReq, u16 wValue,
 		/* Change bits are all write 1 to clear */
 		xhci_writel(xhci, temp | status, addr);
 		temp = xhci_readl(xhci, addr);
-		xhci_dbg(xhci, "clear port %s change, actual port %d status  = 0x%x\n",
-				port_change_bit, wIndex, temp);
+		xhci_dbg(xhci, XHCI_LOG_PORTS,
+				"Clear port %d %s change,"
+				" actual status  = 0x%x\n",
+				wIndex, port_change_bit, temp);
 		temp = xhci_readl(xhci, addr); /* unblock any posted writes */
 		break;
 	default:
diff --git a/drivers/usb/host/xhci-mem.c b/drivers/usb/host/xhci-mem.c
index b8fd270..cf7fbee 100644
--- a/drivers/usb/host/xhci-mem.c
+++ b/drivers/usb/host/xhci-mem.c
@@ -41,15 +41,15 @@ static struct xhci_segment *xhci_segment_alloc(struct xhci_hcd *xhci, gfp_t flag
 	seg = kzalloc(sizeof *seg, flags);
 	if (!seg)
 		return 0;
-	xhci_dbg(xhci, "Allocating priv segment structure at %p\n", seg);
 
 	seg->trbs = dma_pool_alloc(xhci->segment_pool, flags, &dma);
 	if (!seg->trbs) {
 		kfree(seg);
 		return 0;
 	}
-	xhci_dbg(xhci, "// Allocating segment at %p (virtual) 0x%llx (DMA)\n",
-			seg->trbs, (unsigned long long)dma);
+	xhci_dbg(xhci, XHCI_LOG_RINGS,
+			"Allocating DMA segment at 0x%llx (DMA)\n",
+			(unsigned long long)dma);
 
 	memset(seg->trbs, 0, SEGMENT_SIZE);
 	seg->dma = dma;
@@ -63,12 +63,12 @@ static void xhci_segment_free(struct xhci_hcd *xhci, struct xhci_segment *seg)
 	if (!seg)
 		return;
 	if (seg->trbs) {
-		xhci_dbg(xhci, "Freeing DMA segment at %p (virtual) 0x%llx (DMA)\n",
-				seg->trbs, (unsigned long long)seg->dma);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Freeing DMA segment at 0x%llx (DMA)\n",
+				(unsigned long long)seg->dma);
 		dma_pool_free(xhci->segment_pool, seg->trbs, seg->dma);
 		seg->trbs = NULL;
 	}
-	xhci_dbg(xhci, "Freeing priv segment structure at %p\n", seg);
 	kfree(seg);
 }
 
@@ -99,9 +99,6 @@ static void xhci_link_segments(struct xhci_hcd *xhci, struct xhci_segment *prev,
 			val |= TRB_CHAIN;
 		prev->trbs[TRBS_PER_SEGMENT-1].link.control = val;
 	}
-	xhci_dbg(xhci, "Linking segment 0x%llx to segment 0x%llx (DMA)\n",
-			(unsigned long long)prev->dma,
-			(unsigned long long)next->dma);
 }
 
 /* XXX: Do we need the hcd structure in all these functions? */
@@ -114,7 +111,7 @@ void xhci_ring_free(struct xhci_hcd *xhci, struct xhci_ring *ring)
 		return;
 	first_seg = ring->first_seg;
 	seg = first_seg->next;
-	xhci_dbg(xhci, "Freeing ring at %p\n", ring);
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Freeing ring at %p\n", ring);
 	while (seg != first_seg) {
 		struct xhci_segment *next = seg->next;
 		xhci_segment_free(xhci, seg);
@@ -139,7 +136,6 @@ static struct xhci_ring *xhci_ring_alloc(struct xhci_hcd *xhci,
 	struct xhci_segment	*prev;
 
 	ring = kzalloc(sizeof *(ring), flags);
-	xhci_dbg(xhci, "Allocating ring at %p\n", ring);
 	if (!ring)
 		return 0;
 
@@ -169,9 +165,6 @@ static struct xhci_ring *xhci_ring_alloc(struct xhci_hcd *xhci,
 	if (link_trbs) {
 		/* See section 4.9.2.1 and 6.4.4.1 */
 		prev->trbs[TRBS_PER_SEGMENT-1].link.control |= (LINK_TOGGLE);
-		xhci_dbg(xhci, "Wrote link toggle flag to"
-				" segment %p (virtual), 0x%llx (DMA)\n",
-				prev, (unsigned long long)prev->dma);
 	}
 	/* The ring is empty, so the enqueue pointer == dequeue pointer */
 	ring->enqueue = ring->first_seg->trbs;
@@ -287,6 +280,8 @@ int xhci_alloc_virt_device(struct xhci_hcd *xhci, int slot_id,
 		xhci_warn(xhci, "Bad Slot ID %d\n", slot_id);
 		return 0;
 	}
+	xhci_dbg(xhci, XHCI_LOG_DEVICE_STATE,
+			"Allocate device structure for slot ID %i\n", slot_id);
 
 	xhci->devs[slot_id] = kzalloc(sizeof(*xhci->devs[slot_id]), flags);
 	if (!xhci->devs[slot_id])
@@ -298,17 +293,11 @@ int xhci_alloc_virt_device(struct xhci_hcd *xhci, int slot_id,
 	if (!dev->out_ctx)
 		goto fail;
 
-	xhci_dbg(xhci, "Slot %d output ctx = 0x%llx (dma)\n", slot_id,
-			(unsigned long long)dev->out_ctx->dma);
-
 	/* Allocate the (input) device context for address device command */
 	dev->in_ctx = xhci_alloc_container_ctx(xhci, XHCI_CTX_TYPE_INPUT, flags);
 	if (!dev->in_ctx)
 		goto fail;
 
-	xhci_dbg(xhci, "Slot %d input ctx = 0x%llx (dma)\n", slot_id,
-			(unsigned long long)dev->in_ctx->dma);
-
 	/* Initialize the cancellation list for each endpoint */
 	for (i = 0; i < 31; i++)
 		INIT_LIST_HEAD(&dev->eps[i].cancelled_td_list);
@@ -323,10 +312,6 @@ int xhci_alloc_virt_device(struct xhci_hcd *xhci, int slot_id,
 
 	/* Point to output device context in dcbaa. */
 	xhci->dcbaa->dev_context_ptrs[slot_id] = dev->out_ctx->dma;
-	xhci_dbg(xhci, "Set slot id %d dcbaa entry %p to 0x%llx\n",
-			slot_id,
-			&xhci->dcbaa->dev_context_ptrs[slot_id],
-			(unsigned long long) xhci->dcbaa->dev_context_ptrs[slot_id]);
 
 	return 1;
 fail:
@@ -375,7 +360,7 @@ int xhci_setup_addressable_virt_dev(struct xhci_hcd *xhci, struct usb_device *ud
 		slot_ctx->dev_info |= (u32) SLOT_SPEED_LS;
 		break;
 	case USB_SPEED_VARIABLE:
-		xhci_dbg(xhci, "FIXME xHCI doesn't support wireless speeds\n");
+		xhci_warn(xhci, "FIXME xHCI doesn't support wireless speeds\n");
 		return -EINVAL;
 		break;
 	default:
@@ -387,7 +372,6 @@ int xhci_setup_addressable_virt_dev(struct xhci_hcd *xhci, struct usb_device *ud
 			top_dev = top_dev->parent)
 		/* Found device below root hub */;
 	slot_ctx->dev_info2 |= (u32) ROOT_HUB_PORT(top_dev->portnum);
-	xhci_dbg(xhci, "Set root hub portnum to %d\n", top_dev->portnum);
 
 	/* Is this a LS/FS device under a HS hub? */
 	if ((udev->speed == USB_SPEED_LOW || udev->speed == USB_SPEED_FULL) &&
@@ -397,8 +381,6 @@ int xhci_setup_addressable_virt_dev(struct xhci_hcd *xhci, struct usb_device *ud
 		if (udev->tt->multi)
 			slot_ctx->dev_info |= DEV_MTT;
 	}
-	xhci_dbg(xhci, "udev->tt = %p\n", udev->tt);
-	xhci_dbg(xhci, "udev->ttport = 0x%x\n", udev->ttport);
 
 	/* Step 4 - ring already allocated */
 	/* Step 5 */
@@ -419,7 +401,7 @@ int xhci_setup_addressable_virt_dev(struct xhci_hcd *xhci, struct usb_device *ud
 		ep0_ctx->ep_info2 |= MAX_PACKET(8);
 		break;
 	case USB_SPEED_VARIABLE:
-		xhci_dbg(xhci, "FIXME xHCI doesn't support wireless speeds\n");
+		xhci_warn(xhci, "FIXME xHCI doesn't support wireless speeds\n");
 		return -EINVAL;
 		break;
 	default:
@@ -569,7 +551,7 @@ int xhci_endpoint_init(struct xhci_hcd *xhci,
 		max_packet = ep->desc.wMaxPacketSize;
 		ep_ctx->ep_info2 |= MAX_PACKET(max_packet);
 		/* dig out max burst from ep companion desc */
-		if (!ep->ss_ep_comp) {
+		if (!ep->ss_ep_comp && udev->parent) {
 			xhci_warn(xhci, "WARN no SS endpoint companion descriptor.\n");
 			max_packet = 0;
 		} else {
@@ -667,7 +649,8 @@ static int scratchpad_alloc(struct xhci_hcd *xhci, gfp_t flags)
 	struct device *dev = xhci_to_hcd(xhci)->self.controller;
 	int num_sp = HCS_MAX_SCRATCHPAD(xhci->hcs_params2);
 
-	xhci_dbg(xhci, "Allocating %d scratchpad buffers\n", num_sp);
+	xhci_dbg(xhci, XHCI_LOG_INIT,
+			"Allocating %d scratchpad buffers\n", num_sp);
 
 	if (!num_sp)
 		return 0;
@@ -812,17 +795,14 @@ void xhci_mem_cleanup(struct xhci_hcd *xhci)
 		pci_free_consistent(pdev, size,
 				xhci->erst.entries, xhci->erst.erst_dma_addr);
 	xhci->erst.entries = NULL;
-	xhci_dbg(xhci, "Freed ERST\n");
 	if (xhci->event_ring)
 		xhci_ring_free(xhci, xhci->event_ring);
 	xhci->event_ring = NULL;
-	xhci_dbg(xhci, "Freed event ring\n");
 
 	xhci_write_64(xhci, 0, &xhci->op_regs->cmd_ring);
 	if (xhci->cmd_ring)
 		xhci_ring_free(xhci, xhci->cmd_ring);
 	xhci->cmd_ring = NULL;
-	xhci_dbg(xhci, "Freed command ring\n");
 
 	for (i = 1; i < MAX_HC_SLOTS; ++i)
 		xhci_free_virt_device(xhci, i);
@@ -830,12 +810,10 @@ void xhci_mem_cleanup(struct xhci_hcd *xhci)
 	if (xhci->segment_pool)
 		dma_pool_destroy(xhci->segment_pool);
 	xhci->segment_pool = NULL;
-	xhci_dbg(xhci, "Freed segment pool\n");
 
 	if (xhci->device_pool)
 		dma_pool_destroy(xhci->device_pool);
 	xhci->device_pool = NULL;
-	xhci_dbg(xhci, "Freed device context pool\n");
 
 	xhci_write_64(xhci, 0, &xhci->op_regs->dcbaa_ptr);
 	if (xhci->dcbaa)
@@ -859,32 +837,33 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 	int i;
 
 	page_size = xhci_readl(xhci, &xhci->op_regs->page_size);
-	xhci_dbg(xhci, "Supported page size register = 0x%x\n", page_size);
 	for (i = 0; i < 16; i++) {
 		if ((0x1 & page_size) != 0)
 			break;
 		page_size = page_size >> 1;
 	}
 	if (i < 16)
-		xhci_dbg(xhci, "Supported page size of %iK\n", (1 << (i+12)) / 1024);
+		xhci_dbg(xhci, XHCI_LOG_INIT,
+				"Supported page size of %iK\n",
+				(1 << (i+12)) / 1024);
 	else
 		xhci_warn(xhci, "WARN: no supported page size\n");
 	/* Use 4K pages, since that's common and the minimum the HC supports */
 	xhci->page_shift = 12;
 	xhci->page_size = 1 << xhci->page_shift;
-	xhci_dbg(xhci, "HCD page size set to %iK\n", xhci->page_size / 1024);
+	xhci_dbg(xhci, XHCI_LOG_INIT,
+			"HCD page size set to %iK\n", xhci->page_size / 1024);
 
 	/*
 	 * Program the Number of Device Slots Enabled field in the CONFIG
 	 * register with the max value of slots the HC can handle.
 	 */
 	val = HCS_MAX_SLOTS(xhci_readl(xhci, &xhci->cap_regs->hcs_params1));
-	xhci_dbg(xhci, "// xHC can handle at most %d device slots.\n",
+	xhci_dbg(xhci, XHCI_LOG_INIT,
+			"xHC can handle at most %d device slots.\n",
 			(unsigned int) val);
 	val2 = xhci_readl(xhci, &xhci->op_regs->config_reg);
 	val |= (val2 & ~HCS_SLOTS_MASK);
-	xhci_dbg(xhci, "// Setting Max device slots reg = 0x%x.\n",
-			(unsigned int) val);
 	xhci_writel(xhci, val, &xhci->op_regs->config_reg);
 
 	/*
@@ -897,8 +876,6 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 		goto fail;
 	memset(xhci->dcbaa, 0, sizeof *(xhci->dcbaa));
 	xhci->dcbaa->dma = dma;
-	xhci_dbg(xhci, "// Device context base array address = 0x%llx (DMA), %p (virt)\n",
-			(unsigned long long)xhci->dcbaa->dma, xhci->dcbaa);
 	xhci_write_64(xhci, dma, &xhci->op_regs->dcbaa_ptr);
 
 	/*
@@ -917,25 +894,23 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 		goto fail;
 
 	/* Set up the command ring to have one segments for now. */
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Allocating command ring\n");
 	xhci->cmd_ring = xhci_ring_alloc(xhci, 1, true, flags);
 	if (!xhci->cmd_ring)
 		goto fail;
-	xhci_dbg(xhci, "Allocated command ring at %p\n", xhci->cmd_ring);
-	xhci_dbg(xhci, "First segment DMA is 0x%llx\n",
-			(unsigned long long)xhci->cmd_ring->first_seg->dma);
 
 	/* Set the address in the Command Ring Control register */
 	val_64 = xhci_read_64(xhci, &xhci->op_regs->cmd_ring);
 	val_64 = (val_64 & (u64) CMD_RING_RSVD_BITS) |
 		(xhci->cmd_ring->first_seg->dma & (u64) ~CMD_RING_RSVD_BITS) |
 		xhci->cmd_ring->cycle_state;
-	xhci_dbg(xhci, "// Setting command ring address to 0x%x\n", val);
 	xhci_write_64(xhci, val_64, &xhci->op_regs->cmd_ring);
 	xhci_dbg_cmd_ptrs(xhci);
 
 	val = xhci_readl(xhci, &xhci->cap_regs->db_off);
 	val &= DBOFF_MASK;
-	xhci_dbg(xhci, "// Doorbell array is located at offset 0x%x"
+	xhci_dbg(xhci, XHCI_LOG_INIT,
+			"Doorbell array is located at offset 0x%x"
 			" from cap regs base addr\n", val);
 	xhci->dba = (void *) xhci->cap_regs + val;
 	xhci_dbg_regs(xhci);
@@ -947,7 +922,7 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 	 * Event ring setup: Allocate a normal ring, but also setup
 	 * the event ring segment table (ERST).  Section 4.9.3.
 	 */
-	xhci_dbg(xhci, "// Allocating event ring\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Allocating event ring\n");
 	xhci->event_ring = xhci_ring_alloc(xhci, ERST_NUM_SEGS, false, flags);
 	if (!xhci->event_ring)
 		goto fail;
@@ -956,16 +931,10 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 			sizeof(struct xhci_erst_entry)*ERST_NUM_SEGS, &dma);
 	if (!xhci->erst.entries)
 		goto fail;
-	xhci_dbg(xhci, "// Allocated event ring segment table at 0x%llx\n",
-			(unsigned long long)dma);
 
 	memset(xhci->erst.entries, 0, sizeof(struct xhci_erst_entry)*ERST_NUM_SEGS);
 	xhci->erst.num_entries = ERST_NUM_SEGS;
 	xhci->erst.erst_dma_addr = dma;
-	xhci_dbg(xhci, "Set ERST to 0; private num segs = %i, virt addr = %p, dma addr = 0x%llx\n",
-			xhci->erst.num_entries,
-			xhci->erst.entries,
-			(unsigned long long)xhci->erst.erst_dma_addr);
 
 	/* set ring base address and size for each segment table entry */
 	for (val = 0, seg = xhci->event_ring->first_seg; val < ERST_NUM_SEGS; val++) {
@@ -980,14 +949,9 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 	val = xhci_readl(xhci, &xhci->ir_set->erst_size);
 	val &= ERST_SIZE_MASK;
 	val |= ERST_NUM_SEGS;
-	xhci_dbg(xhci, "// Write ERST size = %i to ir_set 0 (some bits preserved)\n",
-			val);
 	xhci_writel(xhci, val, &xhci->ir_set->erst_size);
 
-	xhci_dbg(xhci, "// Set ERST entries to point to event ring.\n");
 	/* set the segment table base address */
-	xhci_dbg(xhci, "// Set ERST base address for ir_set 0 = 0x%llx\n",
-			(unsigned long long)xhci->erst.erst_dma_addr);
 	val_64 = xhci_read_64(xhci, &xhci->ir_set->erst_base);
 	val_64 &= ERST_PTR_MASK;
 	val_64 |= (xhci->erst.erst_dma_addr & (u64) ~ERST_PTR_MASK);
@@ -995,7 +959,6 @@ int xhci_mem_init(struct xhci_hcd *xhci, gfp_t flags)
 
 	/* Set the event ring dequeue address */
 	xhci_set_hc_event_deq(xhci);
-	xhci_dbg(xhci, "Wrote ERST address to ir_set 0.\n");
 	xhci_print_ir_set(xhci, xhci->ir_set, 0);
 
 	/*
diff --git a/drivers/usb/host/xhci-pci.c b/drivers/usb/host/xhci-pci.c
index 06595ec..0610bc7 100644
--- a/drivers/usb/host/xhci-pci.c
+++ b/drivers/usb/host/xhci-pci.c
@@ -41,9 +41,9 @@ static int xhci_pci_reinit(struct xhci_hcd *xhci, struct pci_dev *pdev)
 
 	/* PCI Memory-Write-Invalidate cycle support is optional (uncommon) */
 	if (!pci_set_mwi(pdev))
-		xhci_dbg(xhci, "MWI active\n");
+		xhci_dbg(xhci, XHCI_LOG_INIT, "MWI active\n");
 
-	xhci_dbg(xhci, "Finished xhci_pci_reinit\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Finished xhci_pci_reinit\n");
 	return 0;
 }
 
@@ -73,7 +73,8 @@ static int xhci_pci_setup(struct usb_hcd *hcd)
 			pdev->device == PCI_DEVICE_ID_FRESCO_LOGIC_PDK &&
 			pdev->revision == 0x0) {
 			xhci->quirks |= XHCI_RESET_EP_QUIRK;
-			xhci_dbg(xhci, "QUIRK: Fresco Logic xHC needs configure"
+			xhci_dbg(xhci, XHCI_LOG_QUIRKS,
+					"QUIRK: Fresco Logic xHC needs config"
 					" endpoint cmd after reset endpoint\n");
 	}
 
@@ -82,22 +83,20 @@ static int xhci_pci_setup(struct usb_hcd *hcd)
 	if (retval)
 		return retval;
 
-	xhci_dbg(xhci, "Resetting HCD\n");
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Resetting HCD\n");
 	/* Reset the internal HC memory state and registers. */
 	retval = xhci_reset(xhci);
 	if (retval)
 		return retval;
-	xhci_dbg(xhci, "Reset complete\n");
 
-	xhci_dbg(xhci, "Calling HCD init\n");
 	/* Initialize HCD and host controller data structures. */
 	retval = xhci_init(hcd);
 	if (retval)
 		return retval;
-	xhci_dbg(xhci, "Called HCD init\n");
 
 	pci_read_config_byte(pdev, XHCI_SBRN_OFFSET, &xhci->sbrn);
-	xhci_dbg(xhci, "Got SBRN %u\n", (unsigned int) xhci->sbrn);
+	xhci_dbg(xhci, XHCI_LOG_INIT, "Got SBRN %u\n",
+			(unsigned int) xhci->sbrn);
 
 	/* Find any debug ports */
 	return xhci_pci_reinit(xhci, pdev);
diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index 821b7b4..d71faf5 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -144,10 +144,10 @@ static void inc_deq(struct xhci_hcd *xhci, struct xhci_ring *ring, bool consumer
 	while (last_trb(xhci, ring, ring->deq_seg, next)) {
 		if (consumer && last_trb_on_last_seg(xhci, ring, ring->deq_seg, next)) {
 			ring->cycle_state = (ring->cycle_state ? 0 : 1);
-			if (!in_interrupt())
-				xhci_dbg(xhci, "Toggle cycle state for ring %p = %i\n",
-						ring,
-						(unsigned int) ring->cycle_state);
+			xhci_dbg(xhci, (XHCI_LOG_QUIRKS | XHCI_LOG_RINGS),
+					"Toggle cycle state for ring %p = %i\n",
+					ring,
+					(unsigned int) ring->cycle_state);
 		}
 		ring->deq_seg = ring->deq_seg->next;
 		ring->dequeue = ring->deq_seg->trbs;
@@ -155,11 +155,14 @@ static void inc_deq(struct xhci_hcd *xhci, struct xhci_ring *ring, bool consumer
 	}
 	addr = (unsigned long long) xhci_trb_virt_to_dma(ring->deq_seg, ring->dequeue);
 	if (ring == xhci->event_ring)
-		xhci_dbg(xhci, "Event ring deq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Event ring deq = 0x%llx (DMA)\n", addr);
 	else if (ring == xhci->cmd_ring)
-		xhci_dbg(xhci, "Command ring deq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Command ring deq = 0x%llx (DMA)\n", addr);
 	else
-		xhci_dbg(xhci, "Ring deq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Ring deq = 0x%llx (DMA)\n", addr);
 }
 
 /*
@@ -181,6 +184,7 @@ static void inc_enq(struct xhci_hcd *xhci, struct xhci_ring *ring, bool consumer
 	u32 chain;
 	union xhci_trb *next;
 	unsigned long long addr;
+	unsigned int temp;
 
 	chain = ring->enqueue->generic.field[3] & TRB_CHAIN;
 	next = ++(ring->enqueue);
@@ -209,11 +213,11 @@ static void inc_enq(struct xhci_hcd *xhci, struct xhci_ring *ring, bool consumer
 			}
 			/* Toggle the cycle bit after the last ring segment. */
 			if (last_trb_on_last_seg(xhci, ring, ring->enq_seg, next)) {
+				temp = ring->cycle_state;
 				ring->cycle_state = (ring->cycle_state ? 0 : 1);
-				if (!in_interrupt())
-					xhci_dbg(xhci, "Toggle cycle state for ring %p = %i\n",
-							ring,
-							(unsigned int) ring->cycle_state);
+				xhci_dbg(xhci, XHCI_LOG_RINGS,
+						"Toggle cycle state for ring "
+						"%p = %i\n", ring, temp);
 			}
 		}
 		ring->enq_seg = ring->enq_seg->next;
@@ -222,11 +226,14 @@ static void inc_enq(struct xhci_hcd *xhci, struct xhci_ring *ring, bool consumer
 	}
 	addr = (unsigned long long) xhci_trb_virt_to_dma(ring->enq_seg, ring->enqueue);
 	if (ring == xhci->event_ring)
-		xhci_dbg(xhci, "Event ring enq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Event ring enq = 0x%llx (DMA)\n", addr);
 	else if (ring == xhci->cmd_ring)
-		xhci_dbg(xhci, "Command ring enq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Command ring enq = 0x%llx (DMA)\n", addr);
 	else
-		xhci_dbg(xhci, "Ring enq = 0x%llx (DMA)\n", addr);
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Ring enq = 0x%llx (DMA)\n", addr);
 }
 
 /*
@@ -275,7 +282,6 @@ void xhci_set_hc_event_deq(struct xhci_hcd *xhci)
 	 * there might be more events to service.
 	 */
 	temp &= ~ERST_EHB;
-	xhci_dbg(xhci, "// Write event ring dequeue pointer, preserving EHB bit\n");
 	xhci_write_64(xhci, ((u64) deq & (u64) ~ERST_PTR_MASK) | temp,
 			&xhci->ir_set->erst_dequeue);
 }
@@ -285,7 +291,7 @@ void xhci_ring_cmd_db(struct xhci_hcd *xhci)
 {
 	u32 temp;
 
-	xhci_dbg(xhci, "// Ding dong!\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Ding dong! (Command ring)\n");
 	temp = xhci_readl(xhci, &xhci->dba->doorbell[0]) & DB_MASK;
 	xhci_writel(xhci, temp | DB_TARGET_HOST, &xhci->dba->doorbell[0]);
 	/* Flush PCI posted writes */
@@ -369,19 +375,16 @@ void xhci_find_new_dequeue_state(struct xhci_hcd *xhci,
 	dma_addr_t addr;
 
 	state->new_cycle_state = 0;
-	xhci_dbg(xhci, "Finding segment containing stopped TRB.\n");
 	state->new_deq_seg = find_trb_seg(cur_td->start_seg,
 			dev->eps[ep_index].stopped_trb,
 			&state->new_cycle_state);
 	if (!state->new_deq_seg)
 		BUG();
 	/* Dig out the cycle state saved by the xHC during the stop ep cmd */
-	xhci_dbg(xhci, "Finding endpoint context\n");
 	ep_ctx = xhci_get_ep_ctx(xhci, dev->out_ctx, ep_index);
 	state->new_cycle_state = 0x1 & ep_ctx->deq;
 
 	state->new_deq_ptr = cur_td->last_trb;
-	xhci_dbg(xhci, "Finding segment containing last TRB in TD.\n");
 	state->new_deq_seg = find_trb_seg(state->new_deq_seg,
 			state->new_deq_ptr,
 			&state->new_cycle_state);
@@ -395,12 +398,12 @@ void xhci_find_new_dequeue_state(struct xhci_hcd *xhci,
 	next_trb(xhci, ep_ring, &state->new_deq_seg, &state->new_deq_ptr);
 
 	/* Don't update the ring cycle state for the producer (us). */
-	xhci_dbg(xhci, "New dequeue segment = %p (virtual)\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "Found new ring dequeue pointer.\n");
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "New dequeue segment = %p (virtual)\n",
 			state->new_deq_seg);
 	addr = xhci_trb_virt_to_dma(state->new_deq_seg, state->new_deq_ptr);
-	xhci_dbg(xhci, "New dequeue pointer = 0x%llx (DMA)\n",
+	xhci_dbg(xhci, XHCI_LOG_RINGS, "New dequeue pointer = 0x%llx (DMA)\n",
 			(unsigned long long) addr);
-	xhci_dbg(xhci, "Setting dequeue pointer in internal ring state.\n");
 	ep_ring->dequeue = state->new_deq_ptr;
 	ep_ring->deq_seg = state->new_deq_seg;
 }
@@ -420,13 +423,6 @@ static void td_to_noop(struct xhci_hcd *xhci, struct xhci_ring *ep_ring,
 			 * leave the pointers intact.
 			 */
 			cur_trb->generic.field[3] &= ~TRB_CHAIN;
-			xhci_dbg(xhci, "Cancel (unchain) link TRB\n");
-			xhci_dbg(xhci, "Address = %p (0x%llx dma); "
-					"in seg %p (0x%llx dma)\n",
-					cur_trb,
-					(unsigned long long)xhci_trb_virt_to_dma(cur_seg, cur_trb),
-					cur_seg,
-					(unsigned long long)cur_seg->dma);
 		} else {
 			cur_trb->generic.field[0] = 0;
 			cur_trb->generic.field[1] = 0;
@@ -434,12 +430,6 @@ static void td_to_noop(struct xhci_hcd *xhci, struct xhci_ring *ep_ring,
 			/* Preserve only the cycle bit of this TRB */
 			cur_trb->generic.field[3] &= TRB_CYCLE;
 			cur_trb->generic.field[3] |= TRB_TYPE(TRB_TR_NOOP);
-			xhci_dbg(xhci, "Cancel TRB %p (0x%llx dma) "
-					"in seg %p (0x%llx dma)\n",
-					cur_trb,
-					(unsigned long long)xhci_trb_virt_to_dma(cur_seg, cur_trb),
-					cur_seg,
-					(unsigned long long)cur_seg->dma);
 		}
 		if (cur_trb == cur_td->last_trb)
 			break;
@@ -456,7 +446,8 @@ void xhci_queue_new_dequeue_state(struct xhci_hcd *xhci,
 {
 	struct xhci_virt_ep *ep = &xhci->devs[slot_id]->eps[ep_index];
 
-	xhci_dbg(xhci, "Set TR Deq Ptr cmd, new deq seg = %p (0x%llx dma), "
+	xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_COMMANDS),
+			"Set TR Deq Ptr cmd, new deq seg = %p (0x%llx dma), "
 			"new deq ptr = %p (0x%llx dma), new cycle = %u\n",
 			deq_state->new_deq_seg,
 			(unsigned long long)deq_state->new_deq_seg->dma,
@@ -517,9 +508,6 @@ static void handle_stopped_endpoint(struct xhci_hcd *xhci,
 	 */
 	list_for_each(entry, &ep->cancelled_td_list) {
 		cur_td = list_entry(entry, struct xhci_td, cancelled_td_list);
-		xhci_dbg(xhci, "Cancelling TD starting at %p, 0x%llx (dma).\n",
-				cur_td->first_trb,
-				(unsigned long long)xhci_trb_virt_to_dma(cur_td->start_seg, cur_td->first_trb));
 		/*
 		 * If we stopped on the TD we need to cancel, then we have to
 		 * move the xHC endpoint ring dequeue pointer past this TD.
@@ -568,7 +556,8 @@ static void handle_stopped_endpoint(struct xhci_hcd *xhci,
 		cur_td->urb->hcpriv = NULL;
 		usb_hcd_unlink_urb_from_ep(xhci_to_hcd(xhci), cur_td->urb);
 
-		xhci_dbg(xhci, "Giveback cancelled URB %p\n", cur_td->urb);
+		xhci_dbg(xhci, XHCI_LOG_TX,
+				"Giveback cancelled URB %p\n", cur_td->urb);
 		spin_unlock(&xhci->lock);
 		/* Doesn't matter what we pass for status, since the core will
 		 * just overwrite it (because the URB has been unlinked).
@@ -623,7 +612,7 @@ static void handle_set_deq_completion(struct xhci_hcd *xhci,
 			ep_state &= EP_STATE_MASK;
 			slot_state = slot_ctx->dev_state;
 			slot_state = GET_SLOT_STATE(slot_state);
-			xhci_dbg(xhci, "Slot state = %u, EP state = %u\n",
+			xhci_warn(xhci, "Slot state = %u, EP state = %u\n",
 					slot_state, ep_state);
 			break;
 		case COMP_EBADSLT:
@@ -643,8 +632,9 @@ static void handle_set_deq_completion(struct xhci_hcd *xhci,
 		 * cancelling URBs, which might not be an error...
 		 */
 	} else {
-		xhci_dbg(xhci, "Successful Set TR Deq Ptr cmd, deq = @%08llx\n",
-				ep_ctx->deq);
+		xhci_dbg(xhci, (XHCI_LOG_RINGS | XHCI_LOG_COMMANDS),
+				"Successful Set TR Deq Ptr cmd, "
+				"deq = @%08llx\n", ep_ctx->deq);
 	}
 
 	dev->eps[ep_index].ep_state &= ~SET_DEQ_PENDING;
@@ -665,7 +655,8 @@ static void handle_reset_ep_completion(struct xhci_hcd *xhci,
 	/* This command will only fail if the endpoint wasn't halted,
 	 * but we don't care.
 	 */
-	xhci_dbg(xhci, "Ignoring reset ep completion code of %u\n",
+	xhci_dbg(xhci, XHCI_LOG_COMMANDS_VERBOSE,
+			"Ignoring reset ep completion code of %u\n",
 			(unsigned int) GET_COMP_CODE(event->status));
 
 	/* HW with the reset endpoint quirk needs to have a configure endpoint
@@ -673,7 +664,8 @@ static void handle_reset_ep_completion(struct xhci_hcd *xhci,
 	 * because the HW can't handle two commands being queued in a row.
 	 */
 	if (xhci->quirks & XHCI_RESET_EP_QUIRK) {
-		xhci_dbg(xhci, "Queueing configure endpoint command\n");
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Queueing configure endpoint command\n");
 		xhci_queue_configure_endpoint(xhci,
 				xhci->devs[slot_id]->in_ctx->dma, slot_id,
 				false);
@@ -774,7 +766,8 @@ static void handle_cmd_completion(struct xhci_hcd *xhci,
 			break;
 		}
 		ep_state = xhci->devs[slot_id]->eps[ep_index].ep_state;
-		xhci_dbg(xhci, "Completed config ep cmd - last ep index = %d, "
+		xhci_dbg(xhci, XHCI_LOG_COMMANDS,
+				"Completed config ep cmd - last ep index = %d, "
 				"state = %d\n", ep_index, ep_state);
 		if (xhci->quirks & XHCI_RESET_EP_QUIRK &&
 				ep_state & EP_HALTED) {
@@ -831,7 +824,8 @@ static void handle_port_status(struct xhci_hcd *xhci,
 	}
 	/* FIXME: core doesn't care about all port link state changes yet */
 	port_id = GET_PORT_ID(event->generic.field[0]);
-	xhci_dbg(xhci, "Port Status Change Event for port %d\n", port_id);
+	xhci_dbg(xhci, XHCI_LOG_PORTS,
+			"Port Status Change Event for port %d\n", port_id);
 
 	/* Update event ring dequeue pointer before dropping the lock */
 	inc_deq(xhci, xhci->event_ring, true);
@@ -922,7 +916,6 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 	struct xhci_ep_ctx *ep_ctx;
 	u32 trb_comp_code;
 
-	xhci_dbg(xhci, "In %s\n", __func__);
 	slot_id = TRB_TO_SLOT_ID(event->flags);
 	xdev = xhci->devs[slot_id];
 	if (!xdev) {
@@ -932,7 +925,6 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 
 	/* Endpoint ID is 1 based, our index is zero based */
 	ep_index = TRB_TO_EP_ID(event->flags) - 1;
-	xhci_dbg(xhci, "%s - ep index = %d\n", __func__, ep_index);
 	ep = &xdev->eps[ep_index];
 	ep_ring = ep->ring;
 	ep_ctx = xhci_get_ep_ctx(xhci, xdev->out_ctx, ep_index);
@@ -943,39 +935,40 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 
 	event_dma = event->buffer;
 	/* This TRB should be in the TD at the head of this ring's TD list */
-	xhci_dbg(xhci, "%s - checking for list empty\n", __func__);
 	if (list_empty(&ep_ring->td_list)) {
 		xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
 				TRB_TO_SLOT_ID(event->flags), ep_index);
-		xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
+		xhci_warn(xhci, "Event TRB with TRB type ID %u\n",
 				(unsigned int) (event->flags & TRB_TYPE_BITMASK)>>10);
 		xhci_print_trb_offsets(xhci, (union xhci_trb *) event);
 		urb = NULL;
 		goto cleanup;
 	}
-	xhci_dbg(xhci, "%s - getting list entry\n", __func__);
 	td = list_entry(ep_ring->td_list.next, struct xhci_td, td_list);
 
 	/* Is this a TRB in the currently executing TD? */
-	xhci_dbg(xhci, "%s - looking for TD\n", __func__);
 	event_seg = trb_in_td(ep_ring->deq_seg, ep_ring->dequeue,
 			td->last_trb, event_dma);
-	xhci_dbg(xhci, "%s - found event_seg = %p\n", __func__, event_seg);
 	if (!event_seg) {
 		/* HC is busted, give up! */
 		xhci_err(xhci, "ERROR Transfer event TRB DMA ptr not part of current TD\n");
 		return -ESHUTDOWN;
 	}
 	event_trb = &event_seg->trbs[(event_dma - event_seg->dma) / sizeof(*event_trb)];
-	xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Event TRB with TRB type ID %u\n",
 			(unsigned int) (event->flags & TRB_TYPE_BITMASK)>>10);
-	xhci_dbg(xhci, "Offset 0x00 (buffer lo) = 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Offset 0x00 (buffer lo) = 0x%x\n",
 			lower_32_bits(event->buffer));
-	xhci_dbg(xhci, "Offset 0x04 (buffer hi) = 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Offset 0x04 (buffer hi) = 0x%x\n",
 			upper_32_bits(event->buffer));
-	xhci_dbg(xhci, "Offset 0x08 (transfer length) = 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Offset 0x08 (transfer length) = 0x%x\n",
 			(unsigned int) event->transfer_len);
-	xhci_dbg(xhci, "Offset 0x0C (flags) = 0x%x\n",
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Offset 0x0C (flags) = 0x%x\n",
 			(unsigned int) event->flags);
 
 	/* Look for common error cases */
@@ -988,13 +981,13 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 	case COMP_SHORT_TX:
 		break;
 	case COMP_STOP:
-		xhci_dbg(xhci, "Stopped on Transfer TRB\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "Stopped on Transfer TRB\n");
 		break;
 	case COMP_STOP_INVAL:
-		xhci_dbg(xhci, "Stopped on No-op or Link TRB\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "Stopped on No-op or Link TRB\n");
 		break;
 	case COMP_STALL:
-		xhci_warn(xhci, "WARN: Stalled endpoint\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "Stalled endpoint\n");
 		ep->ep_state |= EP_HALTED;
 		status = -EPIPE;
 		break;
@@ -1003,11 +996,11 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 		status = -EILSEQ;
 		break;
 	case COMP_TX_ERR:
-		xhci_warn(xhci, "WARN: transfer error on endpoint\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "Transfer error on endpoint\n");
 		status = -EPROTO;
 		break;
 	case COMP_BABBLE:
-		xhci_warn(xhci, "WARN: babble error on endpoint\n");
+		xhci_dbg(xhci, XHCI_LOG_TX, "Babble error on endpoint\n");
 		status = -EOVERFLOW;
 		break;
 	case COMP_DB_ERR:
@@ -1032,12 +1025,15 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 				xhci_warn(xhci, "WARN: Success on ctrl data TRB without IOC set??\n");
 				status = -ESHUTDOWN;
 			} else {
-				xhci_dbg(xhci, "Successful control transfer!\n");
+				xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+						"Successful "
+						"control transfer!\n");
 				status = 0;
 			}
 			break;
 		case COMP_SHORT_TX:
-			xhci_warn(xhci, "WARN: short transfer on control ep\n");
+			xhci_dbg(xhci, XHCI_LOG_TX,
+					"Short transfer on control ep\n");
 			if (td->urb->transfer_flags & URB_SHORT_NOT_OK)
 				status = -EREMOTEIO;
 			else
@@ -1099,7 +1095,9 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 					td->urb->actual_length =
 						td->urb->transfer_buffer_length -
 						TRB_LEN(event->transfer_len);
-					xhci_dbg(xhci, "Waiting for status stage event\n");
+					xhci_dbg(xhci, XHCI_LOG_TX,
+							"Waiting for "
+							"status stage event\n");
 					urb = NULL;
 					goto cleanup;
 				}
@@ -1118,10 +1116,12 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 					status = 0;
 			} else {
 				if (usb_endpoint_xfer_bulk(&td->urb->ep->desc))
-					xhci_dbg(xhci, "Successful bulk "
+					xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+							"Successful bulk "
 							"transfer!\n");
 				else
-					xhci_dbg(xhci, "Successful interrupt "
+					xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+							"Successful interrupt "
 							"transfer!\n");
 				status = 0;
 			}
@@ -1136,9 +1136,10 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 			/* Others already handled above */
 			break;
 		}
-		dev_dbg(&td->urb->dev->dev,
-				"ep %#x - asked for %d bytes, "
+		xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+				"slot ID %u, ep %#x - asked for %d bytes, "
 				"%d bytes untransferred\n",
+				td->urb->dev->slot_id,
 				td->urb->ep->desc.bEndpointAddress,
 				td->urb->transfer_buffer_length,
 				TRB_LEN(event->transfer_len));
@@ -1272,7 +1273,8 @@ cleanup:
 	/* FIXME for multi-TD URBs (who have buffers bigger than 64MB) */
 	if (urb) {
 		usb_hcd_unlink_urb_from_ep(xhci_to_hcd(xhci), urb);
-		xhci_dbg(xhci, "Giveback URB %p, len = %d, status = %d\n",
+		xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+				"Giveback URB %p, len = %d, status = %d\n",
 				urb, urb->actual_length, status);
 		spin_unlock(&xhci->lock);
 		usb_hcd_giveback_urb(xhci_to_hcd(xhci), urb, status);
@@ -1291,7 +1293,6 @@ void xhci_handle_event(struct xhci_hcd *xhci)
 	int update_ptrs = 1;
 	int ret;
 
-	xhci_dbg(xhci, "In %s\n", __func__);
 	if (!xhci->event_ring || !xhci->event_ring->dequeue) {
 		xhci->error_bitmask |= 1 << 1;
 		return;
@@ -1304,25 +1305,18 @@ void xhci_handle_event(struct xhci_hcd *xhci)
 		xhci->error_bitmask |= 1 << 2;
 		return;
 	}
-	xhci_dbg(xhci, "%s - OS owns TRB\n", __func__);
 
 	/* FIXME: Handle more event types. */
 	switch ((event->event_cmd.flags & TRB_TYPE_BITMASK)) {
 	case TRB_TYPE(TRB_COMPLETION):
-		xhci_dbg(xhci, "%s - calling handle_cmd_completion\n", __func__);
 		handle_cmd_completion(xhci, &event->event_cmd);
-		xhci_dbg(xhci, "%s - returned from handle_cmd_completion\n", __func__);
 		break;
 	case TRB_TYPE(TRB_PORT_STATUS):
-		xhci_dbg(xhci, "%s - calling handle_port_status\n", __func__);
 		handle_port_status(xhci, event);
-		xhci_dbg(xhci, "%s - returned from handle_port_status\n", __func__);
 		update_ptrs = 0;
 		break;
 	case TRB_TYPE(TRB_TRANSFER):
-		xhci_dbg(xhci, "%s - calling handle_tx_event\n", __func__);
 		ret = handle_tx_event(xhci, &event->trans_event);
-		xhci_dbg(xhci, "%s - returned from handle_tx_event\n", __func__);
 		if (ret < 0)
 			xhci->error_bitmask |= 1 << 9;
 		else
@@ -1369,7 +1363,11 @@ static int prepare_ring(struct xhci_hcd *xhci, struct xhci_ring *ep_ring,
 		u32 ep_state, unsigned int num_trbs, gfp_t mem_flags)
 {
 	/* Make sure the endpoint has been added to xHC schedule */
-	xhci_dbg(xhci, "Endpoint state = 0x%x\n", ep_state);
+	if (ep_state != EP_STATE_STOPPED &&
+			ep_state != EP_STATE_RUNNING)
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				"Endpoint state = 0x%x\n", ep_state);
+
 	switch (ep_state) {
 	case EP_STATE_DISABLED:
 		/*
@@ -1384,7 +1382,8 @@ static int prepare_ring(struct xhci_hcd *xhci, struct xhci_ring *ep_ring,
 		/* XXX not sure if this should be -ENOENT or not */
 		return -EINVAL;
 	case EP_STATE_HALTED:
-		xhci_dbg(xhci, "WARN halted endpoint, queueing URB anyway.\n");
+		xhci_dbg(xhci, XHCI_LOG_TX,
+				"Halted endpoint, queueing URB anyway.\n");
 	case EP_STATE_STOPPED:
 	case EP_STATE_RUNNING:
 		break;
@@ -1450,10 +1449,8 @@ static unsigned int count_sg_trbs_needed(struct xhci_hcd *xhci, struct urb *urb)
 	num_sgs = urb->num_sgs;
 	temp = urb->transfer_buffer_length;
 
-	xhci_dbg(xhci, "count sg list trbs: \n");
 	num_trbs = 0;
 	for_each_sg(urb->sg->sg, sg, num_sgs, i) {
-		unsigned int previous_total_trbs = num_trbs;
 		unsigned int len = sg_dma_len(sg);
 
 		/* Scatter gather list entries may cross 64KB boundaries */
@@ -1467,21 +1464,19 @@ static unsigned int count_sg_trbs_needed(struct xhci_hcd *xhci, struct urb *urb)
 			num_trbs++;
 			running_total += TRB_MAX_BUFF_SIZE;
 		}
-		xhci_dbg(xhci, " sg #%d: dma = %#llx, len = %#x (%d), num_trbs = %d\n",
-				i, (unsigned long long)sg_dma_address(sg),
-				len, len, num_trbs - previous_total_trbs);
 
 		len = min_t(int, len, temp);
 		temp -= len;
 		if (temp == 0)
 			break;
 	}
-	xhci_dbg(xhci, "\n");
-	if (!in_interrupt())
-		dev_dbg(&urb->dev->dev, "ep %#x - urb len = %d, sglist used, num_trbs = %d\n",
-				urb->ep->desc.bEndpointAddress,
-				urb->transfer_buffer_length,
-				num_trbs);
+	xhci_dbg(xhci, XHCI_LOG_RINGS,
+			"slot ID %u ep %#x - urb len = %d, "
+			"sglist used, num_trbs = %d\n",
+			urb->dev->slot_id,
+			urb->ep->desc.bEndpointAddress,
+			urb->transfer_buffer_length,
+			num_trbs);
 	return num_trbs;
 }
 
@@ -1539,7 +1534,8 @@ int xhci_queue_intr_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 	 */
 	if (xhci_interval != ep_interval) {
 		if (!printk_ratelimit())
-			dev_dbg(&urb->dev->dev, "Driver uses different interval"
+			xhci_dbg(xhci, XHCI_LOG_TX,
+					"Driver uses different interval"
 					" (%d microframe%s) than xHCI "
 					"(%d microframe%s)\n",
 					ep_interval,
@@ -1604,8 +1600,6 @@ static int queue_bulk_sg_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 	trb_buff_len = min_t(int, trb_buff_len, this_sg_len);
 	if (trb_buff_len > urb->transfer_buffer_length)
 		trb_buff_len = urb->transfer_buffer_length;
-	xhci_dbg(xhci, "First length to xfer from 1st sglist entry = %u\n",
-			trb_buff_len);
 
 	first_trb = true;
 	/* Queue the first TRB, even if it's zero-length */
@@ -1629,7 +1623,8 @@ static int queue_bulk_sg_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 			td->last_trb = ep_ring->enqueue;
 			field |= TRB_IOC;
 		}
-		xhci_dbg(xhci, " sg entry: dma = %#x, len = %#x (%d), "
+		xhci_dbg(xhci, XHCI_LOG_RINGS,
+				" sg entry: dma = %#x, len = %#x (%d), "
 				"64KB boundary at %#x, end dma = %#x\n",
 				(unsigned int) addr, trb_buff_len, trb_buff_len,
 				(unsigned int) (addr + TRB_MAX_BUFF_SIZE) & ~(TRB_MAX_BUFF_SIZE - 1),
@@ -1637,7 +1632,7 @@ static int queue_bulk_sg_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 		if (TRB_MAX_BUFF_SIZE -
 				(addr & ((1 << TRB_MAX_BUFF_SHIFT) - 1)) < trb_buff_len) {
 			xhci_warn(xhci, "WARN: sg dma xfer crosses 64KB boundaries!\n");
-			xhci_dbg(xhci, "Next boundary at %#x, end dma = %#x\n",
+			xhci_warn(xhci, "Next boundary at %#x, end dma = %#x\n",
 					(unsigned int) (addr + TRB_MAX_BUFF_SIZE) & ~(TRB_MAX_BUFF_SIZE - 1),
 					(unsigned int) addr + trb_buff_len);
 		}
@@ -1722,13 +1717,15 @@ int xhci_queue_bulk_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 	}
 	/* FIXME: this doesn't deal with URB_ZERO_PACKET - need one more */
 
-	if (!in_interrupt())
-		dev_dbg(&urb->dev->dev, "ep %#x - urb len = %#x (%d), addr = %#llx, num_trbs = %d\n",
-				urb->ep->desc.bEndpointAddress,
-				urb->transfer_buffer_length,
-				urb->transfer_buffer_length,
-				(unsigned long long)urb->transfer_dma,
-				num_trbs);
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Slot ID %u ep %#x - urb len = %#x (%d), "
+			"addr = %#llx, num_trbs = %d\n",
+			urb->dev->slot_id,
+			urb->ep->desc.bEndpointAddress,
+			urb->transfer_buffer_length,
+			urb->transfer_buffer_length,
+			(unsigned long long)urb->transfer_dma,
+			num_trbs);
 
 	ret = prepare_transfer(xhci, xhci->devs[slot_id], ep_index,
 			num_trbs, urb, &td, mem_flags);
@@ -1823,9 +1820,9 @@ int xhci_queue_ctrl_tx(struct xhci_hcd *xhci, gfp_t mem_flags,
 	if (!urb->setup_packet)
 		return -EINVAL;
 
-	if (!in_interrupt())
-		xhci_dbg(xhci, "Queueing ctrl tx for slot id %d, ep %d\n",
-				slot_id, ep_index);
+	xhci_dbg(xhci, XHCI_LOG_TX_VERBOSE,
+			"Queueing ctrl tx for slot id %d, ep %d\n",
+			slot_id, ep_index);
 	/* 1 TRB for setup, 1 for status */
 	num_trbs = 2;
 	/*
diff --git a/drivers/usb/host/xhci.h b/drivers/usb/host/xhci.h
index 4b254b6..473e485 100644
--- a/drivers/usb/host/xhci.h
+++ b/drivers/usb/host/xhci.h
@@ -1090,6 +1090,19 @@ struct xhci_hcd {
 	unsigned int		quirks;
 #define	XHCI_LINK_TRB_QUIRK	(1 << 0)
 #define XHCI_RESET_EP_QUIRK	(1 << 1)
+	unsigned int		log_level;
+#define XHCI_LOG_QUIRKS			(1 << 0)
+#define XHCI_LOG_COMMANDS		(1 << 1)
+#define XHCI_LOG_COMMANDS_VERBOSE	(1 << 2)
+#define XHCI_LOG_INIT			(1 << 3)
+#define XHCI_LOG_EVENTS			(1 << 4)
+#define XHCI_LOG_DEVICE_STATE		(1 << 5)
+#define XHCI_LOG_TX			(1 << 6)
+#define XHCI_LOG_TX_VERBOSE		(1 << 7)
+#define XHCI_LOG_NOOPS			(1 << 8)
+#define XHCI_LOG_RINGS			(1 << 9)
+#define XHCI_LOG_PORTS			(1 << 10)
+#define XHCI_LOG_REGS			(1 << 11)
 };
 
 /* For testing purposes */
@@ -1112,8 +1125,18 @@ static inline struct usb_hcd *xhci_to_hcd(struct xhci_hcd *xhci)
 #define XHCI_DEBUG	0
 #endif
 
-#define xhci_dbg(xhci, fmt, args...) \
-	do { if (XHCI_DEBUG) dev_dbg(xhci_to_hcd(xhci)->self.controller , fmt , ## args); } while (0)
+#if XHCI_DEBUG
+#define xhci_dbg(xhci, lvl, fmt, args...)			\
+do {								\
+	if (lvl & xhci->log_level)			\
+		dev_dbg(xhci_to_hcd(xhci)->self.controller ,	\
+				fmt , ## args);			\
+} while (0)
+#else
+#define xhci_dbg(xhci, lvl, fmt, args...)			\
+do {} while (0)
+#endif
+
 #define xhci_info(xhci, fmt, args...) \
 	do { if (XHCI_DEBUG) dev_info(xhci_to_hcd(xhci)->self.controller , fmt , ## args); } while (0)
 #define xhci_err(xhci, fmt, args...) \
@@ -1131,7 +1154,7 @@ static inline unsigned int xhci_readl(const struct xhci_hcd *xhci,
 static inline void xhci_writel(struct xhci_hcd *xhci,
 		const unsigned int val, __u32 __iomem *regs)
 {
-	xhci_dbg(xhci,
+	xhci_dbg(xhci, XHCI_LOG_REGS,
 			"`MEM_WRITE_DWORD(3'b000, 32'h%p, 32'h%0x, 4'hf);\n",
 			regs, val);
 	writel(val, regs);
@@ -1161,7 +1184,7 @@ static inline void xhci_write_64(struct xhci_hcd *xhci,
 	u32 val_lo = lower_32_bits(val);
 	u32 val_hi = upper_32_bits(val);
 
-	xhci_dbg(xhci,
+	xhci_dbg(xhci, XHCI_LOG_REGS,
 			"`MEM_WRITE_DWORD(3'b000, 64'h%p, 64'h%0lx, 4'hf);\n",
 			regs, (long unsigned int) val);
 	writel(val_lo, ptr);
-- 
1.6.3.3


[-- Attachment #3: 0002-USB-xhci-Handle-errors-that-cause-endpoint-halts.patch --]
[-- Type: text/x-diff, Size: 5668 bytes --]

>From 1bd817eafb9411f0da8ae97f8e2590864e90bcef Mon Sep 17 00:00:00 2001
From: Sarah Sharp <sarah.a.sharp@linux.intel.com>
Date: Wed, 11 Nov 2009 10:28:44 -0800
Subject: [PATCH 2/2] USB: xhci: Handle errors that cause endpoint halts.

The xHCI 0.95 and 0.96 specification defines several transfer buffer
request completion codes that indicate a USB transaction error occurred.
When a stall, babble, transaction, or split transaction error completion code
is set, the xHCI has halted that endpoint ring.  Software must issue a
Reset Endpoint command and a Set Transfer Ring Dequeue Pointer command
to clean up the halted ring.

The USB device driver is supposed to call into usb_reset_endpoint() when
an endpoint stalls.  That calls into the xHCI driver to issue the proper
commands.  However, drivers don't call that function for the other
errors that cause the xHC to halt the endpoint ring.  If a babble,
transaction, or split transaction error occurs, check if the endpoint
context reports a halted condition, and clean up the endpoint ring if it
does.

Signed-off-by: Sarah Sharp <sarah.a.sharp@linux.intel.com>
Signed-off-by: Greg Kroah-Hartman <gregkh@suse.de>
---
 drivers/usb/host/xhci-ring.c |   79 ++++++++++++++++++++++++++++++++----------
 1 files changed, 60 insertions(+), 19 deletions(-)

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index d71faf5..73954bc 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -894,6 +894,45 @@ static struct xhci_segment *trb_in_td(
 	return 0;
 }
 
+static void xhci_cleanup_halted_endpoint(struct xhci_hcd *xhci,
+		unsigned int slot_id, unsigned int ep_index,
+		struct xhci_td *td, union xhci_trb *event_trb)
+{
+	struct xhci_virt_ep *ep = &xhci->devs[slot_id]->eps[ep_index];
+	ep->ep_state |= EP_HALTED;
+	ep->stopped_td = td;
+	ep->stopped_trb = event_trb;
+	xhci_queue_reset_ep(xhci, slot_id, ep_index);
+	xhci_cleanup_stalled_ring(xhci, td->urb->dev, ep_index);
+	xhci_ring_cmd_db(xhci);
+}
+
+/* Check if an error has halted the endpoint ring.  The class driver will
+ * cleanup the halt for a non-default control endpoint if we indicate a stall.
+ * However, a babble and other errors also halt the endpoint ring, and the class
+ * driver won't clear the halt in that case, so we need to issue a Set Transfer
+ * Ring Dequeue Pointer command manually.
+ */
+static int xhci_requires_manual_halt_cleanup(struct xhci_hcd *xhci,
+		struct xhci_ep_ctx *ep_ctx,
+		unsigned int trb_comp_code)
+{
+	/* TRB completion codes that may require a manual halt cleanup */
+	if (trb_comp_code == COMP_TX_ERR ||
+			trb_comp_code == COMP_BABBLE ||
+			trb_comp_code == COMP_SPLIT_ERR)
+		/* The 0.96 spec says a babbling control endpoint
+		 * is not halted. The 0.96 spec says it is.  Some HW
+		 * claims to be 0.95 compliant, but it halts the control
+		 * endpoint anyway.  Check if a babble halted the
+		 * endpoint.
+		 */
+		if ((ep_ctx->ep_info & EP_STATE_MASK) == EP_STATE_HALTED)
+			return 1;
+
+	return 0;
+}
+
 /*
  * If this function returns an error condition, it means it got a Transfer
  * event with a corrupted Slot ID, Endpoint ID, or TRB DMA address.
@@ -1039,15 +1078,14 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 			else
 				status = 0;
 			break;
-		case COMP_BABBLE:
-			/* The 0.96 spec says a babbling control endpoint
-			 * is not halted. The 0.96 spec says it is.  Some HW
-			 * claims to be 0.95 compliant, but it halts the control
-			 * endpoint anyway.  Check if a babble halted the
-			 * endpoint.
-			 */
-			if (ep_ctx->ep_info != EP_STATE_HALTED)
+
+		default:
+			if (!xhci_requires_manual_halt_cleanup(xhci,
+						ep_ctx, trb_comp_code))
 				break;
+			xhci_dbg(xhci, "TRB error code %u, "
+					"halted endpoint index = %u\n",
+					trb_comp_code, ep_index);
 			/* else fall through */
 		case COMP_STALL:
 			/* Did we transfer part of the data (middle) phase? */
@@ -1059,15 +1097,9 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 			else
 				td->urb->actual_length = 0;
 
-			ep->stopped_td = td;
-			ep->stopped_trb = event_trb;
-			xhci_queue_reset_ep(xhci, slot_id, ep_index);
-			xhci_cleanup_stalled_ring(xhci, td->urb->dev, ep_index);
-			xhci_ring_cmd_db(xhci);
+			xhci_cleanup_halted_endpoint(xhci,
+					slot_id, ep_index, td, event_trb);
 			goto td_cleanup;
-		default:
-			/* Others already handled above */
-			break;
 		}
 		/*
 		 * Did we transfer any data, despite the errors that might have
@@ -1210,16 +1242,25 @@ static int handle_tx_event(struct xhci_hcd *xhci,
 		ep->stopped_td = td;
 		ep->stopped_trb = event_trb;
 	} else {
-		if (trb_comp_code == COMP_STALL ||
-				trb_comp_code == COMP_BABBLE) {
+		if (trb_comp_code == COMP_STALL) {
 			/* The transfer is completed from the driver's
 			 * perspective, but we need to issue a set dequeue
 			 * command for this stalled endpoint to move the dequeue
 			 * pointer past the TD.  We can't do that here because
-			 * the halt condition must be cleared first.
+			 * the halt condition must be cleared first.  Let the
+			 * USB class driver clear the stall later.
 			 */
 			ep->stopped_td = td;
 			ep->stopped_trb = event_trb;
+		} else if (xhci_requires_manual_halt_cleanup(xhci,
+					ep_ctx, trb_comp_code)) {
+			/* Other types of errors halt the endpoint, but the
+			 * class driver doesn't call usb_reset_endpoint() unless
+			 * the error is -EPIPE.  Clear the halted status in the
+			 * xHCI hardware manually.
+			 */
+			xhci_cleanup_halted_endpoint(xhci,
+					slot_id, ep_index, td, event_trb);
 		} else {
 			/* Update ring dequeue pointer */
 			while (ep_ring->dequeue != td->last_trb)
-- 
1.6.3.3

Re: pm_op(): usb_dev_suspend+0x0/0x10 returns -2 on USB device 8087:0020

[Ákos Maróy]

Alan,

in this thread, earlier I wrote:

>> By the way, I noticed above that you have xhci-hcd installed.  As far 
>> as I know, that driver does not yet support system suspend.  You should 
>> try unloading xhci-hcd before doing the suspend (both with and without 
>> CONFIG_USB_DEBUG).
> 
> wow, rmmod xhci - and the suspend goes through fine!

now, I re-installed the system, and suspend doesn't work anymore.

if I have the xhci module loaded, it fails and returns to the screen
right away.

if I unload the xhci module, I get to the character console, and then
the machine hangs there - nothing happens anymore. only a power cycle helps.

I don't know what was different when at least suspend worked :(

I'll try to do some more debugging..


Akos