Bug 85701

Summary: xhci_hcd can't detect new devices after enabling runtime PM and disabling S3 wake
Product: Drivers Reporter: Dmitry Nezhevenko (dion)
Component: USBAssignee: XHCI bugs virtual user (xhci)
Status: NEW ---    
Severity: normal CC: alan, alexey.brodkin, leho, mybigspam, mzimen
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.17 Subsystem:
Regression: No Bisected commit-id:
Attachments: dmesg

Description Dmitry Nezhevenko 2014-10-06 17:55:58 UTC
Created attachment 152661 [details]
dmesg

On Lenovo t440p machine I've xhci_hcd port that doesn't work after enabling runtime PM:

1. Just after boot, rmmod xhci_hcd and modprobe it again:

[  120.595176] xhci_hcd 0000:00:14.0: enabling bus mastering
[  120.595188] xhci_hcd 0000:00:14.0: xHCI Host Controller
[  120.595194] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 1
[  120.595344] xhci_hcd 0000:00:14.0: cache line size of 64 is not supported
[  120.595368] xhci_hcd 0000:00:14.0: irq 29 for MSI/MSI-X
[  120.595420] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[  120.595421] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[  120.595422] usb usb1: Product: xHCI Host Controller
[  120.595422] usb usb1: Manufacturer: Linux 3.17.0+ xhci_hcd
[  120.595423] usb usb1: SerialNumber: 0000:00:14.0
[  120.595512] hub 1-0:1.0: USB hub found
[  120.595533] hub 1-0:1.0: 15 ports detected
[  120.597745] xhci_hcd 0000:00:14.0: xHCI Host Controller
[  120.597748] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 2
[  120.597782] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003
[  120.597783] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[  120.597784] usb usb2: Product: xHCI Host Controller
[  120.597785] usb usb2: Manufacturer: Linux 3.17.0+ xhci_hcd
[  120.597785] usb usb2: SerialNumber: 0000:00:14.0
[  120.597865] hub 2-0:1.0: USB hub found
[  120.597882] hub 2-0:1.0: 6 ports detected
[  120.598504] usb: failed to peer usb2-port4 and usb1-port3 by location (usb2-port4:none) (usb1-port3:usb2-port3)
[  120.598506] usb usb2-port4: failed to peer to usb1-port3 (-16)
[  120.598809] usb: failed to peer usb2-port6 and usb1-port3 by location (usb2-port6:none) (usb1-port3:usb2-port3)
[  120.598810] usb usb2-port6: failed to peer to usb1-port3 (-16)
[  120.909228] usb 1-5: new full-speed USB device number 2 using xhci_hcd
[  121.038496] usb 1-5: No LPM exit latency info found, disabling LPM.
[  121.046968] usb 1-5: New USB device found, idVendor=058f, idProduct=9540
[  121.046971] usb 1-5: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  121.046972] usb 1-5: Product: EMV Smartcard Reader
[  121.046974] usb 1-5: Manufacturer: Generic
[  121.213054] usb 1-7: new full-speed USB device number 3 using xhci_hcd
[  121.343171] usb 1-7: New USB device found, idVendor=138a, idProduct=0017
[  121.343174] usb 1-7: New USB device strings: Mfr=0, Product=0, SerialNumber=1
[  121.343175] usb 1-7: SerialNumber: bd077adaec22
[  121.456997] usb 1-12: new high-speed USB device number 4 using xhci_hcd
[  121.709358] usb 1-12: New USB device found, idVendor=04f2, idProduct=b39a
[  121.709362] usb 1-12: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[  121.709363] usb 1-12: Product: Integrated Camera
[  121.709364] usb 1-12: Manufacturer: SunplusIT INC.
[  121.779568] uvcvideo: Found UVC 1.00 device Integrated Camera (04f2:b39a)
[  121.788387] input: Integrated Camera as /devices/pci0000:00/0000:00:14.0/usb1/1-12/1-12:1.0/input/input20

2. apply power_settings: 

% for F in /sys/bus/usb/devices/*; do test -f $F/power/control && echo auto | sudo tee $F/power/control; done 

[  947.442248] xhci_hcd 0000:00:14.0: PME# enabled
[  947.482119] xhci_hcd 0000:00:14.0: power state changed by ACPI to D3cold

3. disable XHCI in /proc/acpi/wakeup:

% echo XHCI | sudo tee /proc/acpi/wakeup
% cat /proc/acpi/wakeup| grep XHCI
XHCI      S3    *disabled  pci:0000:00:14.0

4. plug some USB device to port:

[ 1072.724884] xhci_hcd 0000:00:14.0: power state changed by ACPI to D0
[ 1072.828927] xhci_hcd 0000:00:14.0: PME# disabled
[ 1072.828951] xhci_hcd 0000:00:14.0: enabling bus mastering
[ 1072.829114] pci_pm_runtime_suspend(): hcd_pci_runtime_suspend+0x0/0x40 [usbcore] returns -16
[ 1072.933036] xhci_hcd 0000:00:14.0: PME# enabled
[ 1072.972798] xhci_hcd 0000:00:14.0: power state changed by ACPI to D3cold

5. device is not detected and not present in lsusb. I'm using smartphone as device and it's starts charging (but doesn't display 'connected' message). Reenabling xhci in /proc/acpi/wakeup doesn't help. Always reproduces.

6. Unplug device, rmmod xhci_hcd and repeat everything again except 3 (don't disable XHCI in /proc/acpi/wakeup):

...
[ 1240.128339] xhci_hcd 0000:00:14.0: PME# enabled
[ 1240.176209] xhci_hcd 0000:00:14.0: power state changed by ACPI to D3cold

7. Plug device again (XHCI is enabled in /proc/acpi/wakeup):

[ 1295.636130] xhci_hcd 0000:00:14.0: power state changed by ACPI to D0
[ 1295.740136] xhci_hcd 0000:00:14.0: PME# disabled
[ 1295.740150] xhci_hcd 0000:00:14.0: enabling bus mastering
[ 1295.740238] pci_pm_runtime_suspend(): hcd_pci_runtime_suspend+0x0/0x40 [usbcore] returns -16
[ 1295.844209] xhci_hcd 0000:00:14.0: PME# enabled
[ 1295.876043] xhci_hcd 0000:00:14.0: power state changed by ACPI to D3cold
[ 1296.667761] xhci_hcd 0000:00:14.0: power state changed by ACPI to D0
[ 1296.771757] xhci_hcd 0000:00:14.0: PME# disabled
[ 1296.771772] xhci_hcd 0000:00:14.0: enabling bus mastering
[ 1296.771860] pci_pm_runtime_suspend(): hcd_pci_runtime_suspend+0x0/0x40 [usbcore] returns -16
[ 1296.987688] usb 1-6: new high-speed USB device number 5 using xhci_hcd
[ 1297.118812] usb 1-6: New USB device found, idVendor=0fca, idProduct=8012
[ 1297.118815] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 1297.118817] usb 1-6: Product: RIM Network Device
[ 1297.118818] usb 1-6: Manufacturer: Research In Motion, Ltd.
[ 1297.118819] usb 1-6: SerialNumber: EBD1BA7B6C5E4765D017A580236520AB97994D33
[ 1297.139270] rndis_host 1-6:1.0: rndis media connect
[ 1297.161920] rndis_host 1-6:1.0 usb0: register 'rndis_host' at usb-0000:00:14.0-6, RNDIS device, 96:eb:cd:0d:5f:e9
[ 1297.173486] rndis_host 1-6:1.0 usb6: renamed from usb0
[ 1297.191666] systemd-udevd[19181]: renamed network interface usb0 to usb6

So now it works as expected. I'm disabling everything from /proc/acpi/wakeup to make sure that laptop will not be resumed by any USB device.
Comment 1 Greg Kroah-Hartman 2014-10-06 18:01:49 UTC
On Mon, Oct 06, 2014 at 05:55:58PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=85701
> 
>             Bug ID: 85701
>            Summary: xhci_hcd can't detect new devices after enabling
>                     runtime PM and disabling S3 wake

Please send to the linux-usb@vger.kernel.org mailing list.
Comment 2 Leho Kraav 2014-10-22 19:50:58 UTC
I'm seeing similar weirdness on Dell E7440, cc-ing myself.

okt   22 21:57:15 papaya kernel: pci_pm_runtime_suspend(): hcd_pci_runtime_suspend+0x0/0x10 returns -16

this error has become a friend since recent kernel versions, 3.16 and up. currently on 3.17.1.

re-cycling loading xhci-hcd module so far has always made everything work again.

reading through the ml thread now to find out more about how to debug this.
Comment 3 Michal Zimen 2015-01-27 09:09:23 UTC
I'm facing similar issues with following configuration:
Kernel: 3.18.0-trunk-amd64 #1 SMP Debian 3.18.3-1~exp1 (2015-01-18).
bluez: 5.23-2

Sometimes it works when re-cycle module or restart bluetooth daemon. 
The issue has impact on my keyboard but sometimes bt mouse also makes troubles.
(keybard sometimes hangs when pressing capslock)
  

[   55.526938] pci_pm_runtime_suspend(): hcd_pci_runtime_suspend+0x0/0x60 [usbcore] returns -16
[  261.649228] xhci_hcd 0000:00:14.0: xHC is not running.
[  281.697231] xhci_hcd 0000:00:14.0: Port resume took longer than 20000 msec, port status = 0x400603
[  749.475112] usb 2-6: USB disconnect, device number 3
[  749.975388] usb 2-6: new full-speed USB device number 5 using xhci_hcd
[  750.104543] usb 2-6: New USB device found, idVendor=8087, idProduct=07dc
[  750.104546] usb 2-6: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[  750.118998] Bluetooth: hci0: read Intel version: 370710018002030d37
[  750.119001] Bluetooth: hci0: Intel device is already patched. patch num: 37
[  759.646932] hid-generic 0005:03F0:044C.0002: unknown main item tag 0x0
[  759.647039] input: HP Touch to Pair Mouse as /devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:256/0005:03F0:044C.0002/input/input15
[  759.647830] hid-generic 0005:03F0:044C.0002: input,hidraw0: BLUETOOTH HID v1.08 Mouse [HP Touch to Pair Mouse] on 0c:8b:fd:c8:d7:ea
[ 3419.121637] hid-generic 0005:045E:07A4.0003: unknown main item tag 0x0
[ 3419.121735] input: Microsoft Sculpt Mobile Keyboard as /devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:256/0005:045E:07A4.0003/input/input16
[ 3419.121836] hid-generic 0005:045E:07A4.0003: input,hidraw0: BLUETOOTH HID v1.02 Keyboard [Microsoft Sculpt Mobile Keyboard] on 0c:8b:fd:c8:d7:ea
[ 3419.122159] hid-generic 0005:03F0:044C.0004: unknown main item tag 0x0
[ 3419.122227] input: HP Touch to Pair Mouse as /devices/pci0000:00/0000:00:14.0/usb2/2-6/2-6:1.0/bluetooth/hci0/hci0:512/0005:03F0:044C.0004/input/input17
[ 3419.122362] hid-generic 0005:03F0:044C.0004: input,hidraw1: BLUETOOTH HID v1.08 Mouse [HP Touch to Pair Mouse] on 0c:8b:fd:c8:d7:ea
[ 4080.086842] bluetoothd[2191]: segfault at 10 ip 00007fae53eb9937 sp 00007fff9e377330 error 4 in bluetoothd[7fae53e7a000+e3000]
[ 7477.381389] perf interrupt took too long (2519 > 2500), lowering kernel.perf_event_max_sample_rate to 50000