On Tue, Nov 1, 2011 at 7:47 AM, Linus Torvalds
<torvalds@xxxxxxxxxxxxxxxxxxxx> wrote:
>
> Will try.
Ok, the delay makes the USB port work for me. I still don't think it's
the *right* approach, though, as per the previous mail. But it does
make that port work.
I also have to say that I think there is something *seriously* rotten
in runtime power management. Maybe it's just this particular laptop,
but look at what happens when I plug a device into this machine with
everything set to be runtime power-managed...
Some background:
- "powertop" used to make everything power-managed
- I tested with two different USB devices just to be sure
- for the last device (which is a serial device, it shows up as
ftdi_sio), in order to show you the crazy behavior, I did
dmesg > before
.. plug in device ..
dmesg > after
diff -u before after > plug-in
- "lsusb -t" output with that device plugged in is:
1-1.3:1.0: No such file or directory
/: Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 5000M
/: Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 480M
|__ Port 1: Dev 4, If 0, Class=vend., Driver=ftdi_sio, 12M
/: Bus 02.Port 1: Dev 1, Class=root_hub, Driver=ehci_hcd/3p, 480M
|__ Port 1: Dev 2, If 0, Class=hub, Driver=hub/8p, 480M
/: Bus 01.Port 1: Dev 1, Class=root_hub, Driver=ehci_hcd/3p, 480M
|__ Port 1: Dev 2, If 0, Class=hub, Driver=hub/6p, 480M
|__ Port 3: Dev 3, If 0, Class=vend., Driver=, 12M
|__ Port 6: Dev 4, If 0, Class='bInterfaceClass 0x0e not yet
handled', Driver=uvcvideo, 480M
|__ Port 6: Dev 4, If 1, Class='bInterfaceClass 0x0e not yet
handled', Driver=uvcvideo, 480M
just to show that the ftdi_sio thing is directly under the xhci root hub.
With that said, appended is the crazy diff of dmesg output ("plug-in").
NOTE! The absolute *only* thing I did was to plug in the one USB
device into the xhci port. Comments/questions:
- That e1000e thing seems to be just coincidence. It seems to happen
every few minutes or so, it just happened to happen three seconds
before the plug-in.
- But that ehci_hcd thing is *not* pure coincidence. It consistently
happens when I plug something into the xhci port. In fact, it seems to
happen for *any* runtime PM event, because as far as I can tell, it
also happens each time that e1000e thing happens. WTF?
IOW, there seems to be some random cross-talk between devices, where
that stupid ehci thing happens every time something else should
happen. Notice in the trace below how the ehci spewage happens both at
1010 (e1000e power event) and at 1013 (xhci plug-in event).
Ideas?
Linus
---
[torvalds@i5 ~]$ cat plug-in
--- before 2011-11-01 08:39:40.879845372 -0700
+++ after 2011-11-01 08:39:51.551876692 -0700
@@ -1343,3 +1343,82 @@
[ 991.782223] ehci_hcd 0000:00:1a.0: PCI INT A disabled
[ 991.782310] ehci_hcd 0000:00:1a.0: PME# enabled
[ 991.798187] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D3
+[ 1009.853589] e1000e: em1 NIC Link is Down
+[ 1010.169574] e1000e 0000:00:19.0: PME# enabled
+[ 1010.200364] e1000e 0000:00:19.0: BAR 0: set to [mem
0xf2600000-0xf261ffff] (PCI address [0xf2600000-0xf261ffff])
+[ 1010.200380] e1000e 0000:00:19.0: BAR 1: set to [mem
0xf262b000-0xf262bfff] (PCI address [0xf262b000-0xf262bfff])
+[ 1010.200393] e1000e 0000:00:19.0: BAR 2: set to [io 0x5080-0x509f]
(PCI address [0x5080-0x509f])
+[ 1010.200427] e1000e 0000:00:19.0: restoring config space at offset
0xf (was 0x100, writing 0x10a)
+[ 1010.200467] e1000e 0000:00:19.0: restoring config space at offset
0x1 (was 0x100000, writing 0x100007)
+[ 1010.200524] e1000e 0000:00:19.0: PME# disabled
+[ 1010.200664] e1000e 0000:00:19.0: irq 42 for MSI/MSI-X
+[ 1010.345194] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1010.359983] ehci_hcd 0000:00:1a.0: BAR 0: set to [mem
0xf262a000-0xf262a3ff] (PCI address [0xf262a000-0xf262a3ff])
+[ 1010.360008] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1010.360040] ehci_hcd 0000:00:1a.0: restoring config space at
offset 0xf (was 0x100, writing 0x10b)
+[ 1010.360081] ehci_hcd 0000:00:1a.0: restoring config space at
offset 0x1 (was 0x2900000, writing 0x2900002)
+[ 1010.360132] ehci_hcd 0000:00:1a.0: PME# disabled
+[ 1010.360143] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1010.360151] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1010.360168] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level,
low) -> IRQ 16
+[ 1010.360181] ehci_hcd 0000:00:1a.0: setting latency timer to 64
+[ 1010.360221] ehci_hcd 0000:00:1a.0: PCI INT A disabled
+[ 1010.360289] ehci_hcd 0000:00:1a.0: PME# enabled
+[ 1010.360330] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1010.375954] ehci_hcd 0000:00:1d.0: BAR 0: set to [mem
0xf2629000-0xf26293ff] (PCI address [0xf2629000-0xf26293ff])
+[ 1010.375979] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1010.376010] ehci_hcd 0000:00:1d.0: restoring config space at
offset 0xf (was 0x100, writing 0x10a)
+[ 1010.376051] ehci_hcd 0000:00:1d.0: restoring config space at
offset 0x1 (was 0x2900000, writing 0x2900002)
+[ 1010.376103] ehci_hcd 0000:00:1d.0: PME# disabled
+[ 1010.376114] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1010.376122] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1010.376140] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level,
low) -> IRQ 23
+[ 1010.376153] ehci_hcd 0000:00:1d.0: setting latency timer to 64
+[ 1010.376194] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D3
+[ 1010.376225] ehci_hcd 0000:00:1d.0: PCI INT A disabled
+[ 1010.376294] ehci_hcd 0000:00:1d.0: PME# enabled
+[ 1010.391929] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D3
+[ 1013.660675] xhci_hcd 0000:0f:00.0: PME# disabled
+[ 1013.660704] xhci_hcd 0000:0f:00.0: setting latency timer to 64
+[ 1013.666892] pci_pm_runtime_suspend():
hcd_pci_runtime_suspend+0x0/0x20 returns -16
+[ 1013.895959] usb 3-1: new full-speed USB device number 4 using xhci_hcd
+[ 1013.923417] xhci_hcd 0000:0f:00.0: WARN: Stalled endpoint
+[ 1013.925383] xhci_hcd 0000:0f:00.0: WARN: Stalled endpoint
+[ 1013.927351] xhci_hcd 0000:0f:00.0: WARN: Stalled endpoint
+[ 1013.943380] xhci_hcd 0000:0f:00.0: WARN: short transfer on control ep
+[ 1013.958341] xhci_hcd 0000:0f:00.0: WARN: short transfer on control ep
+[ 1013.963336] xhci_hcd 0000:0f:00.0: WARN: short transfer on control ep
+[ 1013.970317] xhci_hcd 0000:0f:00.0: WARN: short transfer on control ep
+[ 1013.971239] usb 3-1: New USB device found, idVendor=0403, idProduct=f680
+[ 1013.971253] usb 3-1: New USB device strings: Mfr=1, Product=2,
SerialNumber=3
+[ 1013.971262] usb 3-1: Product: Suunto Sports Instrument
+[ 1013.971268] usb 3-1: Manufacturer: Suunto
+[ 1013.971276] usb 3-1: SerialNumber: ST000001
+[ 1013.987154] xhci_hcd 0000:0f:00.0: WARN: short transfer on control ep
+[ 1013.992035] ftdi_sio 3-1:1.0: FTDI USB Serial Device converter detected
+[ 1013.992233] usb 3-1: Detected FT232BM
+[ 1013.992243] usb 3-1: Number of endpoints 2
+[ 1013.992247] usb 3-1: Endpoint 1 MaxPacketSize 64
+[ 1013.992251] usb 3-1: Endpoint 2 MaxPacketSize 64
+[ 1013.992255] usb 3-1: Setting MaxPacketSize 64
+[ 1013.997243] usb 3-1: FTDI USB Serial Device converter now attached
to ttyUSB0
+[ 1014.005550] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1014.019703] ehci_hcd 0000:00:1a.0: BAR 0: set to [mem
0xf262a000-0xf262a3ff] (PCI address [0xf262a000-0xf262a3ff])
+[ 1014.019726] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1014.019758] ehci_hcd 0000:00:1a.0: restoring config space at
offset 0xf (was 0x100, writing 0x10b)
+[ 1014.019799] ehci_hcd 0000:00:1a.0: restoring config space at
offset 0x1 (was 0x2900000, writing 0x2900002)
+[ 1014.019849] ehci_hcd 0000:00:1a.0: PME# disabled
+[ 1014.019860] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1014.019868] ehci_hcd 0000:00:1a.0: power state changed by ACPI to D0
+[ 1014.019884] ehci_hcd 0000:00:1a.0: PCI INT A -> GSI 16 (level,
low) -> IRQ 16
+[ 1014.019897] ehci_hcd 0000:00:1a.0: setting latency timer to 64
+[ 1014.192066] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1014.207336] ehci_hcd 0000:00:1d.0: BAR 0: set to [mem
0xf2629000-0xf26293ff] (PCI address [0xf2629000-0xf26293ff])
+[ 1014.207361] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1014.207392] ehci_hcd 0000:00:1d.0: restoring config space at
offset 0xf (was 0x100, writing 0x10a)
+[ 1014.207430] ehci_hcd 0000:00:1d.0: restoring config space at
offset 0x1 (was 0x2900000, writing 0x2900002)
+[ 1014.207487] ehci_hcd 0000:00:1d.0: PME# disabled
+[ 1014.207498] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1014.207506] ehci_hcd 0000:00:1d.0: power state changed by ACPI to D0
+[ 1014.207523] ehci_hcd 0000:00:1d.0: PCI INT A -> GSI 23 (level,
low) -> IRQ 23
+[ 1014.207536] ehci_hcd 0000:00:1d.0: setting latency timer to 64
--
To unsubscribe from this list: send the line "unsubscribe linux-pci" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
