Re: 3.8.2: xhci port is dead until pcieport PME# goes to disabled

[Martin Mokrejs <mmokrejs@fold.natur.cuni.cz>]

Hi Sarah,
  in this particular thread, the USB3 socket of the laptop works once
I plugin a device. When I unplug it and insert same or another device it appears
to be dead until I use 'lsusb -vvv'. After that, I see in dmesg the two lines:

[ 1445.597641] pcieport 0000:00:1c.4: PME# disabled
[ 1445.617667] xhci_hcd 0000:0b:00.0: PME# disabled

That's the whole story.
Thank you,
Martin

Sarah Sharp wrote:
> Hi Martin,
> 
> I'm really having trouble following you here.  Please don't try to tell
> me what you think the root cause of the issue is.  Just tell me exactly
> (in a paragraph or less) what your symptoms are.
> 
> Sending lots of log files and lsusb output at me isn't helpful if I
> don't know what your issue is.
> 
> Sarah Sharp
> 
> On Thu, Mar 14, 2013 at 06:30:53PM +0100, Martin Mokrejs wrote:
>> [resend, no dmesg attached]
>>
>> Hi,
>>   happened to me again that I plugged in some devcie into my USB3 socket
>> in my laptop (usually use an external HUB). Don't believe this is a new
>> issue as a whole, I am facing this time to time since 3.3 time when I bought
>> the laptop. 
>>   But now, I realized the first device works but subsequently plugged in
>> devices do not show up until until I run 'lsusb -vv'. Simple 'lsusb -v'
>> or 'lsusb -t' is not enough. The port starts to work after dmesg logs:
>>
>>
>> [ 1445.597641] pcieport 0000:00:1c.4: PME# disabled
>> [ 1445.617667] xhci_hcd 0000:0b:00.0: PME# disabled
>>
>> I believe lsusb -vv while querying for the detailed device info triggers
>> a fix.
>>
>> Funny, but maybe this will help us to understand why my express card slot
>> somehow relates to the USB3 proivided by the TexasInstruments chip. This
>> is a SandyBridge-based Dell Vostro 3550 laptop. I should add that on the usb
>> mailing list about a year ago some TexasInstruments developer published that
>> they had a hardware bug in a "USB redriver", and as my laptop was made in
>> fall 2011 I am likely having having the buggy HW. If I remember right, the
>> report was about the problem that once you pluging a USB2 device into the XHCI
>> slot, subsequently plugged in USB3 devices won't negotiate at SuperSpeed until
>> you power off computer. So, I think I face a different issue but had to mention
>> this.
>>
>> I use pcie_aspm=off on my kernel command line. I tried to catch some usb traffic
>> on the dead port but the file from usbmon is really empty until I do the
>> 'lsusb -vv'. I tried to turn off the usb powersaving at runtime but I do not
>> have the file to do:
>>
>> # echo -n -1 > /sys/bus/usb/devices/3-0\:1.0/power/autosuspend
>>
>> :(
>>
>> # ls -la /sys/bus/usb/devices/3-0\:1.0/power/
>> total 0
>> drwxr-xr-x 2 root root    0 Mar 14 13:11 .
>> drwxr-xr-x 6 root root    0 Mar 14 13:58 ..
>> -rw-r--r-- 1 root root 4096 Mar 14 13:11 async
>> -r--r--r-- 1 root root 4096 Mar 14 13:11 runtime_active_kids
>> -r--r--r-- 1 root root 4096 Mar 14 13:11 runtime_enabled
>> -r--r--r-- 1 root root 4096 Mar 14 13:11 runtime_status
>> -r--r--r-- 1 root root 4096 Mar 14 13:11 runtime_usage
>> #
>>
>> I feel related could be patches under thread: "usb: add usb port auto power off mechanism"
>>
>>
>> Below is a dmesg since a cold boot. I plugged in a mouse into the USB3 socket.
>>
>> [   91.463285] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
>> [   91.463377] xhci_hcd 0000:0b:00.0: PME# enabled
>> [  447.389700] xhci_hcd 0000:0b:00.0: PME# disabled
>> [  447.389711] xhci_hcd 0000:0b:00.0: enabling bus mastering
>> [  447.389787] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
>> [  447.389819] usb usb3: usb wakeup-resume
>>
>> Was detected. Unplugged the mouse. 
>>
>> [  459.600056] usb 3-2: USB disconnect, device number 2
>> [  459.600058] usb 3-2: unregistering device
>> [  459.600059] usb 3-2: unregistering interface 3-2:1.0
>> [  459.600622] xhci_hcd 0000:0b:00.0: shutdown urb ffff88040a641870 ep1in-intr
>> [  459.702564] usb 3-2: usb_disable_device nuking all URBs
>> [  459.707948] usb 3-2: Successful Endpoint Configure command
>> [  459.860892] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
>> [  459.860910] hub 3-0:1.0: hub_suspend
>> [  459.860917] usb usb3: bus auto-suspend, wakeup 1
>> [  459.860981] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
>> [  459.861070] xhci_hcd 0000:0b:00.0: PME# enabled
>>
>> Then I put the mouse back, I think it was not detected after until I did the lsusb
>> trick. I am not sure, sorry, but is not that important. I was repeating test once
>> again and just forgot now this detail. So below just that the mouse got detected,
>> either thanks to lsusb -vv or not.
>>
>> [  536.745422] xhci_hcd 0000:0b:00.0: PME# disabled
>> [  536.745435] xhci_hcd 0000:0b:00.0: enabling bus mastering
>> [  536.745487] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
>> [  536.745493] usb usb3: usb auto-resume
>> [  536.745509] hub 3-0:1.0: hub_resume
>> [  536.745579] hub 3-0:1.0: port 2: status 0301 change 0001
>>
>> Then a mouse disconnect:
>>
>> [  652.232958] usb 3-2: USB disconnect, device number 3
>> [  652.232960] usb 3-2: unregistering device
>> [  652.232961] usb 3-2: unregistering interface 3-2:1.0
>> [  652.233148] xhci_hcd 0000:0b:00.0: shutdown urb ffff88040b1ee288 ep1in-intr
>> [  652.333325] usb 3-2: usb_disable_device nuking all URBs
>> [  652.337096] usb 3-2: Successful Endpoint Configure command
>> [  652.492164] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
>> [  652.492183] hub 3-0:1.0: hub_suspend
>> [  652.492190] usb usb3: bus auto-suspend, wakeup 1
>> [  652.492254] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
>> [  652.492341] xhci_hcd 0000:0b:00.0: PME# enabled
>> [  652.522157] pcieport 0000:00:1c.4: PME# enabled
>>
>> [  688.128198] kmemleak: 1 new suspected memory leaks (see /sys/kernel/debug/kmemleak)
>>
>> Note above two things pcieport started to mess in. I you look what xhci_hcd printed
>> in previous attempts the was NO pcieport involved around, at all. Now, provided
>> that I reported the kmemleak multiple times this year:
>>
>> unreferenced object 0xffff88040b4a0690 (size 256):
>>   comm "swapper/0", pid 1, jiffies 4294937581 (age 17428.760s)
>>   hex dump (first 32 bytes):
>>     00 00 00 00 ad 4e ad de ff ff ff ff 00 00 00 00  .....N..........
>>     ff ff ff ff ff ff ff ff d8 9f 57 82 ff ff ff ff  ..........W.....
>>   backtrace:
>>     [<ffffffff815fcec7>] kmemleak_alloc+0x21/0x3e
>>     [<ffffffff81117ac4>] slab_post_alloc_hook+0x28/0x2a
>>     [<ffffffff8111a18f>] __kmalloc+0xf3/0x105
>>     [<ffffffff8132b20c>] kzalloc.constprop.14+0xe/0x10
>>     [<ffffffff8132b66d>] device_private_init+0x14/0x63
>>     [<ffffffff8132d790>] dev_set_drvdata+0x19/0x2f
>>     [<ffffffff813f19d1>] i801_probe+0x5e/0x41a
>>     [<ffffffff812924d8>] local_pci_probe+0x39/0x61
>>     [<ffffffff812936fb>] pci_device_probe+0xc6/0xf3
>>     [<ffffffff8132dd59>] driver_probe_device+0xa9/0x1c1
>>     [<ffffffff8132decb>] __driver_attach+0x5a/0x7e
>>     [<ffffffff8132c5f3>] bus_for_each_dev+0x5c/0x88
>>     [<ffffffff8132d8f6>] driver_attach+0x19/0x1b
>>     [<ffffffff8132d4c6>] bus_add_driver+0xa8/0x1fa
>>     [<ffffffff8132e33d>] driver_register+0x8c/0x106
>>     [<ffffffff812932f6>] __pci_register_driver+0x5c/0x60
>>
>> I believe this is related to the issue, somehow.
>>
>> Now I started usbmon, so lets follow another attempt to repeat the bug. For clarity,
>> I will plug into the socket a kayboard, and it won't work until I do 'lsusb -vv'.
>> I pressed then space on the keyboard and that worked immediately (keyboard was dead
>> until lsusb -vv and also dmesg did not log anything).
>>
>> So, lsusb -vv:
>>
>> [  802.986036] pcieport 0000:00:1c.4: PME# disabled
>> [  803.016008] xhci_hcd 0000:0b:00.0: PME# disabled
>> [  803.016021] xhci_hcd 0000:0b:00.0: enabling bus mastering
>> [  803.016078] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
>> [  803.016085] usb usb3: usb auto-resume
>> [  803.016103] hub 3-0:1.0: hub_resume
>> [  803.016172] hub 3-0:1.0: port 2: status 0301 change 0001
>>
>> unplug of the keyboard:
>>
>> [  821.621331] usb usb4: usb auto-resume
>> [  821.621347] hub 4-0:1.0: hub_resume
>> [  821.621405] hub 4-0:1.0: state 7 ports 2 chg 0000 evt 0000
>> [  821.622047] hub 4-0:1.0: hub_suspend
>> [  821.622053] usb usb4: bus auto-suspend, wakeup 1
>> [  967.433533] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0004
>> [  967.433768] hub 3-0:1.0: port 2, status 0100, change 0001, 12 Mb/s
>> [  967.433771] usb 3-2: USB disconnect, device number 4
>> [  967.433772] usb 3-2: unregistering device
>> [  967.433775] usb 3-2: unregistering interface 3-2:1.0
>> [  967.433946] xhci_hcd 0000:0b:00.0: shutdown urb ffff88040a641948 ep1in-intr
>> [  967.579130] usb 3-2: usb_disable_device nuking all URBs
>> [  967.584494] usb 3-2: Successful Endpoint Configure command
>> [  967.798027] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
>> [  967.798046] hub 3-0:1.0: hub_suspend
>> [  967.798075] usb usb3: bus auto-suspend, wakeup 1
>> [  967.798155] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
>> [  967.798242] xhci_hcd 0000:0b:00.0: PME# enabled
>> [  967.828015] pcieport 0000:00:1c.4: PME# enabled
>>
>>
>> You see? pcieport is messing with
>> 00:1c.4 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 5 (rev b5) (prog-if 00 [Normal decode])
>>
>> I unplugged and replugged the keyboard multiple times and it did not work, so
>> I connected the mouse used in the very beginning right after cold boot, still
>> not working. But these were likely logged due to that.
>>
>> [ 1063.263014] pcieport 0000:00:1c.4: PME# disabled
>> [ 1063.272918] pcieport 0000:00:1c.4: PME# enabled
>> [ 1063.312915] pcieport 0000:00:1c.4: PME# disabled
>> [ 1063.322906] pcieport 0000:00:1c.4: PME# enabled
>> [ 1070.132666] pcieport 0000:00:1c.4: PME# disabled
>> [ 1070.142559] pcieport 0000:00:1c.4: PME# enabled
>> [ 1070.182601] pcieport 0000:00:1c.4: PME# disabled
>> [ 1070.192644] pcieport 0000:00:1c.4: PME# enabled
>>
>>  After doing 'lsusb -vv' I rescued the USB3 socket and it detected the mouse.
>>
>> [ 1108.504953] pcieport 0000:00:1c.4: PME# disabled
>> [ 1108.525010] xhci_hcd 0000:0b:00.0: PME# disabled
>> [ 1108.525023] xhci_hcd 0000:0b:00.0: enabling bus mastering
>> [ 1108.525069] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_resume: 0
>> [ 1108.525075] usb usb3: usb auto-resume
>> [ 1108.525094] hub 3-0:1.0: hub_resume
>> [ 1108.525196] hub 3-0:1.0: port 2: status 0301 change 0001
>>
>> I unplugged the mouse:
>>
>> [ 1230.618019] usb 3-2: unregistering device
>> [ 1230.618020] usb 3-2: unregistering interface 3-2:1.0
>> [ 1230.618188] xhci_hcd 0000:0b:00.0: shutdown urb ffff88040b1ee288 ep1in-intr
>> [ 1230.711764] usb 3-2: usb_disable_device nuking all URBs
>> [ 1230.715101] usb 3-2: Successful Endpoint Configure command
>> [ 1230.870763] hub 3-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x100
>> [ 1230.870782] hub 3-0:1.0: hub_suspend
>> [ 1230.870797] usb usb3: bus auto-suspend, wakeup 1
>> [ 1230.870862] xhci_hcd 0000:0b:00.0: hcd_pci_runtime_suspend: 0
>> [ 1230.870950] xhci_hcd 0000:0b:00.0: PME# enabled
>> [ 1230.900730] pcieport 0000:00:1c.4: PME# enabled
>>
>>
>> In summary, note that *immediately before the line* "xhci_hcd 0000:0b:00.0: PME# disabled"
>> must appear "pcieport 0000:00:1c.4: PME# disabled". Don't know who is the blocker.
>> But in reverse order the PME# are being enabled after a device is unplugged from the USB3
>> socket.
>>
>> During the tests I had an eSATA in the express card slot since cold boot but don't think
>> it is relevant here. The express slot is 01.c7 device and the card would be 11.0.
>>
>>
>>
>>
>> I will send to Alan and Sarah two files directly (thank you for their inspection): ;)
>>
>> The first part of testing is in usbmon_0u.bin (repeatedly connecting a mouse).
>>
>> The latter in usbmon_0u_mouse_unplug_keyboard_insert.bin. Both files should demonstrate
>> the same issue although in the latter file it might be easier to see because the keyboard
>> was plugged in after a mouse and was not detected until 'lsusb -vv'.
>>
>>
>>
>>
>>
>> Below is when a keyboard is connected to the dead USB3 socket:
>>
>> # diff -u -w lspci_vvvxxx_mouse_unplugged.txt lspci_vvvxxx_mouse_unplugged_keyboard_inserted.txt
>> --- lspci_vvvxxx_mouse_unplugged.txt    2013-03-14 12:22:34.000000000 +0100
>> +++ lspci_vvvxxx_mouse_unplugged_keyboard_inserted.txt  2013-03-14 12:25:06.000000000 +0100
>> @@ -747,7 +747,7 @@
>>         Region 2: Memory at f7d10000 (64-bit, non-prefetchable) [size=8K]
>>         Capabilities: [40] Power Management version 3
>>                 Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=100mA PME(D0+,D1+,D2+,D3hot+,D3cold+)
>> -               Status: D3 NoSoftRst+ PME-Enable+ DSel=0 DScale=0 PME-
>> +               Status: D3 NoSoftRst+ PME-Enable+ DSel=0 DScale=0 PME+
>>         Capabilities: [48] MSI: Enable- Count=1/8 Maskable- 64bit+
>>                 Address: 0000000000000000  Data: 0000
>>         Capabilities: [70] Express (v2) Endpoint, MSI 00
>> @@ -785,7 +785,7 @@
>>  10: 04 00 d0 f7 00 00 00 00 04 00 d1 f7 00 00 00 00
>>  20: 00 00 00 00 00 00 00 00 00 00 00 00 28 10 b3 04
>>  30: 00 00 00 00 40 00 00 00 00 00 00 00 0b 01 00 00
>> -40: 01 48 83 fe 0b 01 00 00 05 70 86 00 00 00 00 00
>> +40: 01 48 83 fe 0b 81 00 00 05 70 86 00 00 00 00 00
>>  50: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>  60: 30 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00
>>  70: 10 c0 02 00 c3 8f 90 05 00 20 19 00 12 3c 07 00
>>
>>
>> Now, when the port is rescued by lsusb -vv, the following can be seen:
>>
>> # diff -u -w lspci_vv_mouse_unplugged_keyboard_inserted.txt lspci_vv_mouse_unplugged_keyboard_inserted_kb_alive.txt
>> --- lspci_vv_mouse_unplugged_keyboard_inserted.txt      2013-03-14 12:25:13.000000000 +0100
>> +++ lspci_vv_mouse_unplugged_keyboard_inserted_kb_alive.txt     2013-03-14 12:26:42.000000000 +0100
>> @@ -276,7 +276,7 @@
>>         Capabilities: [90] Subsystem: Dell Device 04b3
>>         Capabilities: [a0] Power Management version 2
>>                 Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA PME(D0+,D1-,D2-,D3hot+,D3cold+)
>> -               Status: D3 NoSoftRst- PME-Enable+ DSel=0 DScale=0 PME-
>> +               Status: D0 NoSoftRst- PME-Enable- DSel=0 DScale=0 PME-
>>         Kernel driver in use: pcieport
>>  
>>  00:1c.7 PCI bridge: Intel Corporation 6 Series/C200 Series Chipset Family PCI Express Root Port 8 (rev b5) (prog-if 00 [Normal decode])
>> @@ -476,14 +476,15 @@
>>  
>>  0b:00.0 USB controller: Texas Instruments TUSB73x0 SuperSpeed USB 3.0 xHCI Host Controller (rev 02) (prog-if 30 [XHCI])
>>         Subsystem: Dell Device 04b3
>> -       Control: I/O- Mem+ BusMaster- SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
>> +       Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
>>         Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
>> +       Latency: 0, Cache Line Size: 64 bytes
>>         Interrupt: pin A routed to IRQ 16
>>         Region 0: Memory at f7d00000 (64-bit, non-prefetchable) [size=64K]
>>         Region 2: Memory at f7d10000 (64-bit, non-prefetchable) [size=8K]
>>         Capabilities: [40] Power Management version 3
>>                 Flags: PMEClk- DSI- D1+ D2+ AuxCurrent=100mA PME(D0+,D1+,D2+,D3hot+,D3cold+)
>> -               Status: D3 NoSoftRst+ PME-Enable+ DSel=0 DScale=0 PME+
>> +               Status: D0 NoSoftRst+ PME-Enable- DSel=0 DScale=0 PME-
>>         Capabilities: [48] MSI: Enable- Count=1/8 Maskable- 64bit+
>>                 Address: 0000000000000000  Data: 0000
>>         Capabilities: [70] Express (v2) Endpoint, MSI 00
>> #
>>
>>
>>
>> The difference in lsusb output is probably useless as it just shows that once the socket
>> was working the keyboard was picked up by a driver. Looks like yet another PCI issue.
>> At least no diffs in iomem. ;)
>>
>>
>> Thanks,
>> Martin
>>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-pci" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
>