On Sun, 7 May 2017, Paul Menzel wrote: > > > $ journalctl -k | grep -i usb > > ... > > > Mai 07 13:44:19 gm-debian kernel: ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver > > > Mai 07 13:44:19 gm-debian kernel: ehci-pci 0000:00:1d.7: new USB bus registered, assigned bus number 1 > > > Mai 07 13:44:19 gm-debian kernel: uhci_hcd: USB Universal Host Controller Interface driver > > > Mai 07 13:44:19 gm-debian kernel: ehci-pci 0000:00:1d.7: USB 2.0 started, EHCI 1.00 > > > Mai 07 13:44:19 gm-debian kernel: usb usb1: New USB device found, idVendor=1d6b, idProduct=0002 > > > Mai 07 13:44:19 gm-debian kernel: usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 > > > Mai 07 13:44:19 gm-debian kernel: usb usb1: Product: EHCI Host Controller > > > Mai 07 13:44:19 gm-debian kernel: usb usb1: Manufacturer: Linux 4.11.0+ ehci_hcd > > > Mai 07 13:44:19 gm-debian kernel: usb usb1: SerialNumber: 0000:00:1d.7 > > > Mai 07 13:44:19 gm-debian kernel: hub 1-0:1.0: USB hub found > > ... > > > Mai 07 13:44:19 gm-debian kernel: usb 1-6: new high-speed USB device number 2 using ehci-pci > > > Mai 07 13:44:19 gm-debian kernel: usb 1-6: New USB device found, idVendor=17ef, idProduct=1000 > > > Mai 07 13:44:19 gm-debian kernel: usb 1-6: New USB device strings: Mfr=0, Product=0, SerialNumber=0 > > > Mai 07 13:44:19 gm-debian kernel: hub 1-6:1.0: USB hub found > > > > It is a hub, perhaps part of a dock since the vendor is Lenovo. If you > > want to see why it takes so long to resume, a usbmon trace of the EHCI > > bus during the suspend/resume transition would be helpful (see > > Documentation/usb/usbmon.txt). > > Hopefully, I did everything correctly. Unfortunately, the Linux version > 4.12-pre has issues with suspend, so I used Debian’s Linux 4.9 Linux > kernel. I logged the trace right before resume with `systemctl > suspend`, and terminated it afterward. > > ``` > $ lsusb > Bus 005 Device 002: ID 17ef:1000 Lenovo > Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub > Bus 004 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub > Bus 003 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub > Bus 002 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub > Bus 001 Device 001: ID 1d6b:0001 Linux Foundation 1.1 root hub > $ sudo cat /sys/kernel/debug/usb/usbmon/5u Okay. The timestamps below are the second column, and the units are microseconds. This starts partway into the resume of usb5. > f204d9c0 122373641 S Ci:5:001:0 s a3 00 0000 0001 0004 4 < > f204d9c0 122373660 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373669 S Ci:5:001:0 s a3 00 0000 0002 0004 4 < > f204d9c0 122373675 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373680 S Ci:5:001:0 s a3 00 0000 0003 0004 4 < > f204d9c0 122373686 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373690 S Ci:5:001:0 s a3 00 0000 0004 0004 4 < > f204d9c0 122373696 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373701 S Ci:5:001:0 s a3 00 0000 0005 0004 4 < > f204d9c0 122373706 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373711 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f204d9c0 122373716 C Ci:5:001:0 0 4 = 07050000 > f204d9c0 122373721 S Ci:5:001:0 s a3 00 0000 0007 0004 4 < > f204d9c0 122373726 C Ci:5:001:0 0 4 = 00010000 > f204d9c0 122373731 S Ci:5:001:0 s a3 00 0000 0008 0004 4 < > f204d9c0 122373736 C Ci:5:001:0 0 4 = 00010000 > f69fec00 122373741 S Ii:5:001:1 -115:2048 4 < This is the end of the resume of usb5. Total time listed here is 0.1 ms, but that is only a part of the actual time required. Next is the start of the resume of 5-6. > f204d9c0 122373747 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f204d9c0 122373756 C Ci:5:001:0 0 4 = 07050000 > f204d9c0 122373761 S Co:5:001:0 s 23 01 0002 0006 0000 0 > f204d9c0 122373769 C Co:5:001:0 0 0 > f69fec00 122382522 C Ii:5:001:1 0:2048 2 = 0000 > f69fec00 122382526 S Ii:5:001:1 -115:2048 4 < > f69fec00 122412081 C Ii:5:001:1 0:2048 2 = 4000 > f69fec00 122412084 S Ii:5:001:1 -115:2048 4 < > f204d900 122420072 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f204d900 122420137 C Ci:5:001:0 0 4 = 03050400 > f20df000 122440071 S Co:5:001:0 s 23 01 0012 0006 0000 0 > f20df000 122440081 C Co:5:001:0 0 0 > f20df000 122440102 S Ci:5:002:0 s 80 00 0000 0000 0002 2 < > f20df000 122440276 C Ci:5:002:0 0 2 = 0300 > f20df000 122440287 S Co:5:002:0 s 00 01 0001 0000 0000 0 > f20df000 122440393 C Co:5:002:0 0 0 > f20df000 122440403 S Ci:5:002:0 s a3 00 0000 0001 0004 4 < > f20df000 122440518 C Ci:5:002:0 0 4 = 00010000 > f20df000 122440526 S Ci:5:002:0 s a3 00 0000 0002 0004 4 < > f20df000 122440643 C Ci:5:002:0 0 4 = 00010000 > f20df000 122440651 S Ci:5:002:0 s a3 00 0000 0003 0004 4 < > f20df000 122440767 C Ci:5:002:0 0 4 = 00010000 > f20df000 122440775 S Ci:5:002:0 s a3 00 0000 0004 0004 4 < > f20df000 122440892 C Ci:5:002:0 0 4 = 00010000 > f69fce40 122440900 S Ii:5:002:1 -115:2048 1 < This is the end of the resume of 5-6. Total time required was 67.153 ms, nowhere near as large as the 376 ms reported in your earlier test. > f69fce40 122443072 C Ii:5:002:1 -2:2048 0 > f69fec00 122443113 C Ii:5:001:1 -2:2048 0 These two lines show runtime suspends of 5-6 and usb-5. I suppose these might be counted as part of the resume time; they add an extra 2.213 ms. Then about 877 ms later: > f76d79c0 123320332 S Ci:5:001:0 s a3 00 0000 0001 0004 4 < > f76d79c0 123320347 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320376 S Ci:5:001:0 s a3 00 0000 0002 0004 4 < > f76d79c0 123320388 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320418 S Ci:5:001:0 s a3 00 0000 0003 0004 4 < > f76d79c0 123320438 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320459 S Ci:5:001:0 s a3 00 0000 0004 0004 4 < > f76d79c0 123320465 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320487 S Ci:5:001:0 s a3 00 0000 0005 0004 4 < > f76d79c0 123320494 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320515 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f76d79c0 123320525 C Ci:5:001:0 0 4 = 01050100 These show a runtime resume of usb5, caused by an apparently spontaneous disconnect and reconnect of the 5-6 device. However, this must have happened after the system resume was finished. > f76d79c0 123320548 S Co:5:001:0 s 23 01 0010 0006 0000 0 > f76d79c0 123320556 C Co:5:001:0 0 0 > f76d79c0 123320582 S Ci:5:001:0 s a3 00 0000 0007 0004 4 < > f76d79c0 123320588 C Ci:5:001:0 0 4 = 00010000 > f76d79c0 123320612 S Ci:5:001:0 s a3 00 0000 0008 0004 4 < > f76d79c0 123320619 C Ci:5:001:0 0 4 = 00010000 > f69fec00 123428114 S Ii:5:001:1 -115:2048 4 < > f204d900 123428151 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f204d900 123428163 C Ci:5:001:0 0 4 = 01050000 > f204d900 123428180 S Co:5:001:0 s 23 03 0004 0006 0000 0 > f204d900 123428191 C Co:5:001:0 0 0 > f6755000 123488031 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f6755000 123488259 C Ci:5:001:0 0 4 = 03051000 > f6755000 123488282 S Co:5:001:0 s 23 01 0014 0006 0000 0 > f6755000 123488291 C Co:5:001:0 0 0 > f6755000 123556660 S Ci:5:000:0 s 80 06 0100 0000 0040 64 < > f6755000 123556784 C Ci:5:000:0 0 18 = 12010002 09000240 ef170010 01000000 0001 > f6755000 123556802 S Co:5:001:0 s 23 03 0004 0006 0000 0 > f6755000 123556813 C Co:5:001:0 0 0 > f69fef00 123616032 S Ci:5:001:0 s a3 00 0000 0006 0004 4 < > f69fef00 123616260 C Ci:5:001:0 0 4 = 03051000 > f69fef00 123616264 S Co:5:001:0 s 23 01 0014 0006 0000 0 > f69fef00 123616271 C Co:5:001:0 0 0 > f69fef00 123676025 S Co:5:000:0 s 00 05 0002 0000 0000 0 > f69fef00 123676155 C Co:5:000:0 0 0 > f69fef00 123704141 S Ci:5:002:0 s 80 06 0100 0000 0012 18 < > f69fef00 123704289 C Ci:5:002:0 0 18 = 12010002 09000240 ef170010 01000000 0001 > f69fef00 123704312 S Ci:5:002:0 s 80 06 0200 0000 0029 41 < > f69fef00 123704400 C Ci:5:002:0 0 41 = 09022900 010100e0 01090400 00010900 01000705 81030100 0c090400 01010900 > f69fef00 123704429 S Co:5:002:0 s 00 09 0001 0000 0000 0 > f69fef00 123704525 C Co:5:002:0 0 0 > f69fef00 123704570 S Co:5:002:0 s 01 0b 0001 0000 0000 0 > f69fef00 123704659 C Co:5:002:0 0 0 > f69fef00 123704676 S Ci:5:002:0 s 80 00 0000 0000 0002 2 < > f69fef00 123704777 C Ci:5:002:0 0 2 = 0100 > f69fef00 123704800 S Co:5:002:0 s 23 03 0008 0001 0000 0 > f69fef00 123704900 C Co:5:002:0 0 0 > f69fef00 123704926 S Co:5:002:0 s 23 03 0008 0002 0000 0 > f69fef00 123705028 C Co:5:002:0 0 0 > f69fef00 123705054 S Co:5:002:0 s 23 03 0008 0003 0000 0 > f69fef00 123705161 C Co:5:002:0 0 0 > f69fef00 123705182 S Co:5:002:0 s 23 03 0008 0004 0000 0 > f69fef00 123705267 C Co:5:002:0 0 0 > f69fef00 123812020 S Ci:5:002:0 s a3 00 0000 0001 0004 4 < > f69fef00 123812149 C Ci:5:002:0 0 4 = 00010000 > f69fef00 123812161 S Ci:5:002:0 s a3 00 0000 0002 0004 4 < > f69fef00 123812277 C Ci:5:002:0 0 4 = 00010000 > f69fef00 123812297 S Ci:5:002:0 s a3 00 0000 0003 0004 4 < > f69fef00 123812402 C Ci:5:002:0 0 4 = 00010000 Then 5-6 was reset. > f69fce40 123889943 C Ii:5:002:1 -2:2048 0 > f20d2f00 123890343 S Co:5:002:0 s 00 03 0001 0000 0000 0 > f20d2f00 123890517 C Co:5:002:0 0 0 > f20d2f00 123900358 S Co:5:001:0 s 23 03 0002 0006 0000 0 > f20d2f00 123900466 C Co:5:001:0 0 0 > f69fec00 123920061 C Ii:5:001:1 -2:2048 0 And again, runtime suspends of 5-6 and usb5. > ``` > > The Linux messages, full log attached, also contain the lines below. > > ``` > kernel: usb usb1: root hub lost power or was reset > kernel: usb usb2: root hub lost power or was reset > kernel: usb usb3: root hub lost power or was reset > kernel: usb usb4: root hub lost power or was reset > ``` Those are normal. Intel does not follow the UHCI spec on their motherboards, which is a little odd because they were largely responsible for writing the spec in the first place. If you want to get some more details about the timing of the suspends and resumes, enable CONFIG_PRINTK_TIME in your kernel and rebuild drivers/usb/core with -DVERBOSE_DEBUG. Then remember to turn on USB dynamic debugging before you start the test: echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control Alan Stern -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
