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 [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
