On Tue, 9 May 2017, Paul Menzel wrote: > Dear Alan, > > > Am Montag, den 08.05.2017, 16:58 -0400 schrieb Alan Stern: > > On Mon, 8 May 2017, Paul Menzel wrote: > > > > > `CONFIG_PRINTK_TIME` is already selected in the Debian configuration. > > > > That's odd; the kernel timestamps weren't present in the journalctl > > output you posted earlier. > > Do you mean for `kernel: usb usb1: root hub lost power or was reset`? > Sorry, I removed them there to make the lines shorter. No, I meant things like this: Mai 07 13:44:19 gm-debian kernel: ACPI: bus type USB registered Mai 07 13:44:19 gm-debian kernel: usbcore: registered new interface driver usbfs Mai 07 13:44:19 gm-debian kernel: usbcore: registered new interface driver hub Mai 07 13:44:19 gm-debian kernel: usbcore: registered new device driver 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 None of the kernel timestamps are present. Maybe journald removed them; I don't know. In any case, it would be better to use dmesg for displaying the kernel log instead of journalctl. > > > As I have never built a module separately before, and while reading up > > > on it, I remembered, that there is the config option `maxdepth` in pm- > > > graph limiting the depth of the graph by default to five [1]. I > > > increased it to ten now, and, I think, it shows that `hub_port_reset` > > > takes 120 ms twice, though the two `msleeps` only add up to 87 ms the > > > first time. > > > > I'll analyze the ftrace output in more detail tomorrow. > > > > > Please find all the files in the attached archive, and please tell me, > > > if you still want me to rebuild the usbcore kernel module. > > > > Yes, please do. To build just the usbcore module, you can do: > > > > make -DVERBOSE_DEBUG -M drivers/usb/core > > That gave me an error. I used > > ``` > $ make CFLAGS="-DVERBOSE_DEBUG" drivers/usb/core/usbcore.ko > ``` Yes, okay, sorry. Just to be sure that everything gets rebuilt, you should remove all the .o files from drivers/usb/core before running this command. > and copied that module over the present one, rebooted, and did as you > asked. > > ``` > $ echo 'module usbcore =p' | sudo tee /sys/kernel/debug/dynamic_debug/control > […] > $ systemctl suspend > $ journalctl -k -o short-precise | tee /dev/shm/20170509–linux_messages_with_usbcore_verbose_debug.txt > […] > $ grep -i usb /dev/shm/20170509–linux_messages_with_usbcore_verbose_debug.txt Not only does this not contain the kernel timestamps, it also doesn't contain a bunch of debugging messages! I'm specifically referring to all the dev_vdbg() calls in drivers/usb/core/driver.c. Did you filter out messages not containing "usb"? Please don't do that. Some of the most important debugging messages might get lost. Here's the resume portion: > Mai 09 09:12:58.576479 gm-debian kernel: usb usb1: root hub lost power or was reset > Mai 09 09:12:58.576736 gm-debian kernel: usb usb2: root hub lost power or was reset > Mai 09 09:12:58.577008 gm-debian kernel: usb usb4: root hub lost power or was reset > Mai 09 09:12:58.577263 gm-debian kernel: usb usb5: root hub lost power or was reset > Mai 09 09:12:58.578009 gm-debian kernel: usb usb1: usb resume > Mai 09 09:12:58.578268 gm-debian kernel: usb usb2: usb resume > Mai 09 09:12:58.579480 gm-debian kernel: usb usb3: usb resume > Mai 09 09:12:58.579735 gm-debian kernel: usb usb4: usb resume > Mai 09 09:12:58.580502 gm-debian kernel: usb usb5: usb resume > Mai 09 09:12:58.582199 gm-debian kernel: usb usb3-port6: status 0501 change 0001 > Mai 09 09:12:58.582820 gm-debian kernel: usb 3-6: Waited 0ms for CONNECT > Mai 09 09:12:58.583059 gm-debian kernel: usb 3-6: finish reset-resume > Mai 09 09:12:58.584074 gm-debian kernel: usb 3-6: reset high-speed USB device number 2 using ehci-pci This doesn't seem to agree with the sequence of events in the usbmon trace. The trace showed a normal resume following by a reset, not a reset-resume. > Mai 09 09:12:58.586340 gm-debian kernel: usb usb5: bus auto-suspend, wakeup 1 > Mai 09 09:12:58.586933 gm-debian kernel: usb usb3-port6: status 0503, change 0000, 480 Mb/s > Mai 09 09:12:58.588121 gm-debian kernel: usb 3-6: usb auto-suspend, wakeup 1 > Mai 09 09:12:58.588599 gm-debian kernel: usb usb2: bus auto-suspend, wakeup 1 > Mai 09 09:12:58.589079 gm-debian kernel: usb usb1: bus auto-suspend, wakeup 1 > Mai 09 09:12:58.589560 gm-debian kernel: usb usb4: bus auto-suspend, wakeup 1 > Mai 09 09:12:58.590739 gm-debian kernel: usb usb3: bus auto-suspend, wakeup 1 If you believe these timestamps (which I do not!), they show a total resume time of about 14 ms. Obviously that is wrong. This is one reason why it's better to use dmesg for kernel logs. The ftrace information agrees with the kernel log, in that it shows the external hub required a reset-resume, not a normal resume followed by a reset. The total time required for usb_dev_resume() for the 5-6 device was about 221 ms, a little better than your first value of 376 ms but still pretty long. That time was divided up as follows: hub_port_init: 156 ms hub_port_reset: 53 ms msleep: 27 ms msleep: 25 ms hub_port_reset: 83 ms msleep: 50 ms msleep: 32 ms msleep: 12 ms hub_activate: 64 ms hub_power_on: 64 ms msleep: 64 ms The numbers don't add up exactly because I rounded off and included only the most time-consuming activities. As you can see, almost all of the time was spent sleeping. The reason the second hub_port_reset call took longer than the first was because other tasks were running, so the msleeps took longer than requested because the CPU was being used for something else. Thus, at least 30 ms of this time -- and probably more -- was spent running other resume routines. I don't understand why the delay for hub_power_on was so short. According to the definition of hub_power_on_good_delay, it's supposed to last at least 100 ms. Anyway, that's the explanation. The device had to be reset during the resume because it got disconnected from the USB bus at some point during the system sleep. Resetting a USB device is inherently a slow operation; it involves delays whose lengths are prescribed by the USB specification. The same goes for powering on the hub's ports following the reset. 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
