how to know how long it takes on suspend/resume for platform usb driver

how to know how long it takes on suspend/resume for platform usb driver

[loody]

hi all:
I am implementing platform layer suspend/resume usb driver.
Is there kernel configuration or module parameter I can used to
calculate suspend/resume time spend?

-- 
Regards,

Re: how to know how long it takes on suspend/resume for platform usb driver

[Alan Stern]

On Tue, 31 Dec 2013, loody wrote:

> hi all:
> I am implementing platform layer suspend/resume usb driver.
> Is there kernel configuration or module parameter I can used to
> calculate suspend/resume time spend?

Turn on CONFIG_PM_SLEEP_DEBUG, and before starting your test, do

	echo 1 >/sys/power/pm_print_times

Alan Stern

Re: how to know how long it takes on suspend/resume for platform usb driver

[loody]

[-- Attachment #1: Type: text/plain, Size: 2309 bytes --]

hi Alan:


2014/1/1 Alan Stern <stern@rowland.harvard.edu>:
> On Tue, 31 Dec 2013, loody wrote:
>
>> hi all:
>> I am implementing platform layer suspend/resume usb driver.
>> Is there kernel configuration or module parameter I can used to
>> calculate suspend/resume time spend?
>
> Turn on CONFIG_PM_SLEEP_DEBUG, and before starting your test, do
>
>         echo 1 >/sys/power/pm_print_times
>
> Alan Stern
>
I can see log like below:

[  252.311771] call usb2+ returned 0 after 202 usecs
[  252.311778] call usb1+ returned 0 after 239 usecs
[  252.311961] call usb3+ returned 0 after 438 usecs
.........................
[  252.884923] ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
[  252.900401] call 0000:00:1d.0+ returned 0 after 15495 usecs
[  252.900403] calling  0000:00:1c.3+ @ 2587, parent: pci0000:00
[  252.900475] call 0000:00:1c.3+ returned 0 after 68 usecs
[  252.900477] calling  0000:00:1c.2+ @ 2587, parent: pci0000:00
[  252.900547] call 0000:00:1c.2+ returned 0 after 67 usecs
[  252.900548] calling  0000:00:1c.1+ @ 2587, parent: pci0000:00
[  252.900618] call 0000:00:1c.1+ returned 0 after 67 usecs
[  252.900620] calling  0000:00:1c.0+ @ 2587, parent: pci0000:00
[  252.900691] call 0000:00:1c.0+ returned 0 after 68 usecs
[  252.900692] calling  0000:00:1b.0+ @ 2587, parent: pci0000:00
[  252.900694] call 0000:00:1b.0+ returned 0 after 0 usecs
[  252.900695] calling  0000:00:1a.0+ @ 2587, parent: pci0000:00
[  252.901149] ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
[  252.916417] call 0000:00:1a.0+ returned 0 after 15334 usecs
[  252.916419] calling  0000:00:16.0+ @ 2587, parent: pci0000:00
[  252.916469] call 0000:00:16.0+ returned 0 after 47 usecs
[  252.916470] calling  0000:00:14.0+ @ 2587, parent: pci0000:00

I have some questions:
1. "call 0000:00:1d.0+ returned 0 after 15495 usecs" mean all ports
under this ehci host total cost 15495 us for resuming?
2. is it possible to change the order of calling resume callback?
    for example, suppose the original sequence is "ehci -> xhci -> tty
..." and I want to change as "tty-> ehci -> xhci".
3. what is above "usb2+" mean? after trace source code, It seems "type" resume.
    I can tell "bus" resume, since it is bus driver layer resume call back API.
    What is "type" resume?

Appreciate your help,

[-- Attachment #2: suspend.resume.log.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 12896 bytes --]

Re: how to know how long it takes on suspend/resume for platform usb driver

[Alan Stern]

On Sat, 4 Jan 2014, loody wrote:

> hi Alan:
> 
> 
> 2014/1/1 Alan Stern <stern@rowland.harvard.edu>:
> > On Tue, 31 Dec 2013, loody wrote:
> >
> >> hi all:
> >> I am implementing platform layer suspend/resume usb driver.
> >> Is there kernel configuration or module parameter I can used to
> >> calculate suspend/resume time spend?
> >
> > Turn on CONFIG_PM_SLEEP_DEBUG, and before starting your test, do
> >
> >         echo 1 >/sys/power/pm_print_times
> >
> > Alan Stern
> >
> I can see log like below:
> 
> [  252.311771] call usb2+ returned 0 after 202 usecs
> [  252.311778] call usb1+ returned 0 after 239 usecs
> [  252.311961] call usb3+ returned 0 after 438 usecs
> .........................
> [  252.884923] ehci-pci 0000:00:1d.0: System wakeup enabled by ACPI
> [  252.900401] call 0000:00:1d.0+ returned 0 after 15495 usecs
> [  252.900403] calling  0000:00:1c.3+ @ 2587, parent: pci0000:00
> [  252.900475] call 0000:00:1c.3+ returned 0 after 68 usecs
> [  252.900477] calling  0000:00:1c.2+ @ 2587, parent: pci0000:00
> [  252.900547] call 0000:00:1c.2+ returned 0 after 67 usecs
> [  252.900548] calling  0000:00:1c.1+ @ 2587, parent: pci0000:00
> [  252.900618] call 0000:00:1c.1+ returned 0 after 67 usecs
> [  252.900620] calling  0000:00:1c.0+ @ 2587, parent: pci0000:00
> [  252.900691] call 0000:00:1c.0+ returned 0 after 68 usecs
> [  252.900692] calling  0000:00:1b.0+ @ 2587, parent: pci0000:00
> [  252.900694] call 0000:00:1b.0+ returned 0 after 0 usecs
> [  252.900695] calling  0000:00:1a.0+ @ 2587, parent: pci0000:00
> [  252.901149] ehci-pci 0000:00:1a.0: System wakeup enabled by ACPI
> [  252.916417] call 0000:00:1a.0+ returned 0 after 15334 usecs
> [  252.916419] calling  0000:00:16.0+ @ 2587, parent: pci0000:00
> [  252.916469] call 0000:00:16.0+ returned 0 after 47 usecs
> [  252.916470] calling  0000:00:14.0+ @ 2587, parent: pci0000:00
> 
> I have some questions:
> 1. "call 0000:00:1d.0+ returned 0 after 15495 usecs" mean all ports
> under this ehci host total cost 15495 us for resuming?

In the log messages above, 15495 us was the time required for
suspending, not resuming.  It means that putting the host controller
into D3 took 15495 us.  The times required to suspend the root hub and
each port are mentioned elsewhere in the log.

> 2. is it possible to change the order of calling resume callback?
>     for example, suppose the original sequence is "ehci -> xhci -> tty
> ..." and I want to change as "tty-> ehci -> xhci".

It is possible only to a very limited extent.  You can turn async
suspend/resume on or off, and this will affect the order.  Of course,
when async suspend/resume is off, the total time required will be
longer than when it is on.

Why do you want to change the order?  It shouldn't make any difference.

> 3. what is above "usb2+" mean? after trace source code, It seems "type" resume.
>     I can tell "bus" resume, since it is bus driver layer resume call back API.
>     What is "type" resume?

There can be several different "types" of devices all attached to the
same bus.  For example, on a USB bus we have devices representing USB
peripherals, USB interfaces, and USB ports -- three different types.  
A "type" resume is the type-specific resume callback API.  See how
usb_device_type is defined and used in drivers/usb/core/usb.c.

Alan Stern

Re: how to know how long it takes on suspend/resume for platform usb driver

[loody]

[-- Attachment #1: Type: text/plain, Size: 2074 bytes --]

hi alan:

>>
>> I have some questions:
>> 1. "call 0000:00:1d.0+ returned 0 after 15495 usecs" mean all ports
>> under this ehci host total cost 15495 us for resuming?
>
> In the log messages above, 15495 us was the time required for
> suspending, not resuming.  It means that putting the host controller
> into D3 took 15495 us.  The times required to suspend the root hub and
> each port are mentioned elsewhere in the log.
>
Yes. you are correct.
I excerpt the wrong part.

>> 2. is it possible to change the order of calling resume callback?
>>     for example, suppose the original sequence is "ehci -> xhci -> tty
>> ..." and I want to change as "tty-> ehci -> xhci".
>
> It is possible only to a very limited extent.  You can turn async
> suspend/resume on or off, and this will affect the order.  Of course,
> when async suspend/resume is off, the total time required will be
> longer than when it is on.
>
> Why do you want to change the order?  It shouldn't make any difference.
Because I want the GUI and input part of driver resume as earlier as possible.
Such that user can keep on their previous work more quicker.


>
>> 3. what is above "usb2+" mean? after trace source code, It seems "type" resume.
>>     I can tell "bus" resume, since it is bus driver layer resume call back API.
>>     What is "type" resume?
>
> There can be several different "types" of devices all attached to the
> same bus.  For example, on a USB bus we have devices representing USB
> peripherals, USB interfaces, and USB ports -- three different types.
> A "type" resume is the type-specific resume callback API.  See how
> usb_device_type is defined and used in drivers/usb/core/usb.c.

when I "echo 1 > /sys/power/pm_print_time" on my embedded system,
there are some message I am curious.
after we resume ehci by " call platform3-ehci.0+ returned 0 after 7746
usecs" and
type driver "call usb3+ returned 0 after 100475 usecs

why there come below resume message:
"calling  ehci.2+ @ 63, parent: none
bus resume
call ehci.2+ returned 0 after 2 usecs
"

Thanks for your kind help,

[-- Attachment #2: 2014.01.06.pm_pirnt_time.log.tar.bz2 --]
[-- Type: application/x-bzip2, Size: 2742 bytes --]

Re: how to know how long it takes on suspend/resume for platform usb driver

[Alan Stern]

On Mon, 6 Jan 2014, loody wrote:

> >> 2. is it possible to change the order of calling resume callback?
> >>     for example, suppose the original sequence is "ehci -> xhci -> tty
> >> ..." and I want to change as "tty-> ehci -> xhci".
> >
> > It is possible only to a very limited extent.  You can turn async
> > suspend/resume on or off, and this will affect the order.  Of course,
> > when async suspend/resume is off, the total time required will be
> > longer than when it is on.
> >
> > Why do you want to change the order?  It shouldn't make any difference.
> Because I want the GUI and input part of driver resume as earlier as possible.
> Such that user can keep on their previous work more quicker.

I doubt it will make any noticeable difference.  Remember, userspace 
remains frozen until _all_ the devices have been resumed.  Until that 
happens, the user can't do anything.

> when I "echo 1 > /sys/power/pm_print_time" on my embedded system,
> there are some message I am curious.
> after we resume ehci by " call platform3-ehci.0+ returned 0 after 7746
> usecs" and
> type driver "call usb3+ returned 0 after 100475 usecs
> 
> why there come below resume message:
> "calling  ehci.2+ @ 63, parent: none
> bus resume
> call ehci.2+ returned 0 after 2 usecs
> "

Because your system has a device named "ehci.2".  If you look through
the dmesg log for boot-up you should be able to find it.

Alan Stern

Re: how to know how long it takes on suspend/resume for platform usb driver

[loody]

hi all:

2014-01-06 23:10 GMT+08:00 Alan Stern <stern@rowland.harvard.edu>:
> On Mon, 6 Jan 2014, loody wrote:
>
>> >> 2. is it possible to change the order of calling resume callback?
>> >>     for example, suppose the original sequence is "ehci -> xhci -> tty
>> >> ..." and I want to change as "tty-> ehci -> xhci".
>> >
>> > It is possible only to a very limited extent.  You can turn async
>> > suspend/resume on or off, and this will affect the order.  Of course,
>> > when async suspend/resume is off, the total time required will be
>> > longer than when it is on.
>> >
>> > Why do you want to change the order?  It shouldn't make any difference.
>> Because I want the GUI and input part of driver resume as earlier as possible.
>> Such that user can keep on their previous work more quicker.
>
> I doubt it will make any noticeable difference.  Remember, userspace
> remains frozen until _all_ the devices have been resumed.  Until that
> happens, the user can't do anything.

after tracing the kernel src, I found the usb resume call back is
called in drivers/base/power/main.c -> dpm_resume.

is that the only way usb resume functions could be called?
if resume  has bottom half mechanism, is it possible to put usb resume
function at there in stead of first beginning resume step?

thanks for your help,



-- 
Regards,

Re: how to know how long it takes on suspend/resume for platform usb driver

[Alan Stern]

On Thu, 20 Feb 2014, loody wrote:

> hi all:
> 
> 2014-01-06 23:10 GMT+08:00 Alan Stern <stern@rowland.harvard.edu>:
> > On Mon, 6 Jan 2014, loody wrote:
> >
> >> >> 2. is it possible to change the order of calling resume callback?
> >> >>     for example, suppose the original sequence is "ehci -> xhci -> tty
> >> >> ..." and I want to change as "tty-> ehci -> xhci".
> >> >
> >> > It is possible only to a very limited extent.  You can turn async
> >> > suspend/resume on or off, and this will affect the order.  Of course,
> >> > when async suspend/resume is off, the total time required will be
> >> > longer than when it is on.
> >> >
> >> > Why do you want to change the order?  It shouldn't make any difference.
> >> Because I want the GUI and input part of driver resume as earlier as possible.
> >> Such that user can keep on their previous work more quicker.
> >
> > I doubt it will make any noticeable difference.  Remember, userspace
> > remains frozen until _all_ the devices have been resumed.  Until that
> > happens, the user can't do anything.
> 
> after tracing the kernel src, I found the usb resume call back is
> called in drivers/base/power/main.c -> dpm_resume.
> 
> is that the only way usb resume functions could be called?

Yes.

> if resume  has bottom half mechanism, is it possible to put usb resume
> function at there in stead of first beginning resume step?

The USB resume routines do not have bottom halves.

Alan Stern

Re: how to know how long it takes on suspend/resume for platform usb driver

[loody]

hi alan:

2014-02-20 23:53 GMT+08:00 Alan Stern <stern@rowland.harvard.edu>:
> On Thu, 20 Feb 2014, loody wrote:
>
>> hi all:
>>
>> 2014-01-06 23:10 GMT+08:00 Alan Stern <stern@rowland.harvard.edu>:
>> > On Mon, 6 Jan 2014, loody wrote:
>> >
>> >> >> 2. is it possible to change the order of calling resume callback?
>> >> >>     for example, suppose the original sequence is "ehci -> xhci -> tty
>> >> >> ..." and I want to change as "tty-> ehci -> xhci".
>> >> >
>> >> > It is possible only to a very limited extent.  You can turn async
>> >> > suspend/resume on or off, and this will affect the order.  Of course,
>> >> > when async suspend/resume is off, the total time required will be
>> >> > longer than when it is on.
>> >> >
>> >> > Why do you want to change the order?  It shouldn't make any difference.
>> >> Because I want the GUI and input part of driver resume as earlier as possible.
>> >> Such that user can keep on their previous work more quicker.
>> >
>> > I doubt it will make any noticeable difference.  Remember, userspace
>> > remains frozen until _all_ the devices have been resumed.  Until that
>> > happens, the user can't do anything.
>>
>> after tracing the kernel src, I found the usb resume call back is
>> called in drivers/base/power/main.c -> dpm_resume.
>>
>> is that the only way usb resume functions could be called?
>
> Yes.
I found all usb devices will be register as dev->power.async_suspend
=1 in usb_new_device.

if all usb devices' resume will be finished in
drivers/base/power/main.c -> dpm_resume, what is the difference to
register these devices as async_suspend =1?
Doesn't async_schedule in dpm_resume will let those async_suspend =1
devices resume after calling dpm_resume?

Appreciate your kind help,

Re: how to know how long it takes on suspend/resume for platform usb driver

[Alan Stern]

On Fri, 21 Feb 2014, loody wrote:

> >> after tracing the kernel src, I found the usb resume call back is
> >> called in drivers/base/power/main.c -> dpm_resume.
> >>
> >> is that the only way usb resume functions could be called?
> >
> > Yes.
> I found all usb devices will be register as dev->power.async_suspend
> =1 in usb_new_device.
> 
> if all usb devices' resume will be finished in
> drivers/base/power/main.c -> dpm_resume, what is the difference to
> register these devices as async_suspend =1?
> Doesn't async_schedule in dpm_resume will let those async_suspend =1
> devices resume after calling dpm_resume?

Sorry, I should have been more careful in my reply.

The resume routines are always called from device_resume.  If
async_suspend is set to 0 then dpm_resume calls device_resume directly.  
If async_suspend is set to 1 then dpm_resume starts up an async thread,
which calls device_resume indirectly (by way of async_resume).

Alan Stern