[LUCID 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times.
Andy Whitcroft
apw at canonical.com
Fri Feb 12 09:48:06 UTC 2010
On Thu, Feb 11, 2010 at 01:55:35PM -0600, Manoj Iyer wrote:
>
> This patch is an extension to a resume report patch submitted to upstream
> by Rafael J. Wysocki. cnd tested this kernel and reported that it prints
> information correctly. The messages will be printed if suspend/resume of
> driver/device took more than 100ms. This default can be changed in CONFIG.
If we require another patch you should send it in here so we have the
full history. If that patch is full contained in this one then we should
likely pull that one out in its original form for both attribution and
to avoid collisions when we rebase up to that version in the future.
> Feb 11 13:23:05 cndougla kernel: [ 59.848676] PM: suspend of drv:sd
> dev:0:0:0:0 complete after 978.535 msecs
> Feb 11 13:23:05 cndougla kernel: [ 60.110097] PM: suspend of drv:HDA
> Intel dev:0000:00:08.0 complete after 149.996 msecs
> Feb 11 13:23:05 cndougla kernel: [ 60.110433] PM: suspend devices took
> 1.320 seconds
>
> Feb 11 13:23:05 cndougla kernel: [ 61.313617] PM: resume of drv:battery
> dev:PNP0C0A:00 complete after 141.572 msecs
> Feb 11 13:23:05 cndougla kernel: [ 66.300578] PM: resume of drv:nvidia
> dev:0000:02:00.0 complete after 4849.583 msecs
Yeeks how slow is Nvidia. This is exactly the sort of information we
are looking to get out of the debugging exercise.
> Feb 11 13:23:05 cndougla kernel: [ 66.562640] PM: resume of drv:usb
> dev:usb3 complete after 109.993 msecs
> Feb 11 13:23:05 cndougla kernel: [ 66.672636] PM: resume of drv:usb
> dev:usb4 complete after 109.980 msecs
> Feb 11 13:23:05 cndougla kernel: [ 67.076900] PM: resume devices took
> 5.900 seconds
>
>
> The following changes since commit
> a913ef9ba3b23aee8db094d5ab5804777c697ef1:
> Andy Whitcroft (1):
> UBUNTU: Ubuntu-2.6.32-13.18
>
> are available in the git repository at:
>
>
> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git
> srtime
>
> Manoj Iyer (2):
> UBUNTU: SAUCE: PM report driver and device suspend/resume times.
> UBUNTU: [Config] Added CONFIG_SR_REPORT_TIME_LIMIT
>
> debian.master/config/config.common.ubuntu | 1 +
> drivers/base/power/main.c | 35
> +++++++++++++++++++++++++++++
> 2 files changed, 36 insertions(+), 0 deletions(-)
>
>
> From b5c3874a49410d148d662b42bf2d305e83ddfc3e Mon Sep 17 00:00:00 2001
> From: Manoj Iyer <manoj.iyer at canonical.com>
> Date: Thu, 11 Feb 2010 13:35:42 -0600
> Subject: [PATCH 1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times.
>
> This patch prints suspend/resume information for each driver/device to
> dmesg. I don't think it adds much value to upstream.
>
> Signed-off-by: Manoj Iyer <manoj.iyer at canonical.com>
> ---
> drivers/base/power/main.c | 35 +++++++++++++++++++++++++++++++++++
> 1 files changed, 35 insertions(+), 0 deletions(-)
>
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 8aa2443..578b43d 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -29,6 +29,13 @@
> #include "../base.h"
> #include "power.h"
>
> +/* Set default to 100 msecs */
> +#ifdef CONFIG_SR_REPORT_TIME_LIMIT
> +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT
> +#else
> +#define SR_REPORT_TIME_LIMIT 100
> +#endif
> +
If this is a configuration option you should be handling the default
value in the definition of the confuration option and so shouldn't need
this here. You should be able to rely on CONFIG_FOO existing and having
a proper value and just use it in place below.
> /*
> * The entries in the dpm_list list are in a depth first order, simply
> * because children are guaranteed to be discovered after parents, and
> @@ -324,6 +331,26 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info,
> kobject_name(&dev->kobj), pm_verb(state.event), info, error);
> }
>
> +
> +static void device_show_time(struct device *dev, ktime_t starttime, pm_message_t state, char *info)
> +{
> + ktime_t calltime;
> + s64 usecs64;
> + int usecs;
> +
> + calltime = ktime_get();
> + usecs64 = ktime_to_ns(ktime_sub(calltime, starttime));
> + do_div(usecs64, NSEC_PER_USEC);
> + usecs = usecs64;
> + if (usecs == 0)
> + usecs = 1;
> + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT)
> + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event),
> + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC,
> + usecs % USEC_PER_MSEC);
> +}
> +
> +
> /*------------------------- Resume routines -------------------------*/
>
> /**
> @@ -337,6 +364,7 @@ static void pm_dev_err(struct device *dev, pm_message_t state, char *info,
> static int device_resume_noirq(struct device *dev, pm_message_t state)
> {
> int error = 0;
> + ktime_t starttime = ktime_get();
>
> TRACE_DEVICE(dev);
> TRACE_RESUME(0);
> @@ -347,6 +375,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
> if (dev->bus->pm) {
> pm_dev_dbg(dev, state, "EARLY ");
> error = pm_noirq_op(dev, dev->bus->pm, state);
> + device_show_time(dev, starttime, state, "early");
> }
> End:
> TRACE_RESUME(error);
> @@ -388,6 +417,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq);
> static int device_resume(struct device *dev, pm_message_t state)
> {
> int error = 0;
> + ktime_t starttime = ktime_get();
>
> TRACE_DEVICE(dev);
> TRACE_RESUME(0);
> @@ -424,6 +454,7 @@ static int device_resume(struct device *dev, pm_message_t state)
> error = dev->class->resume(dev);
> }
> }
> + device_show_time(dev, starttime, state, NULL);
> End:
> up(&dev->sem);
>
> @@ -583,6 +614,7 @@ static pm_message_t resume_event(pm_message_t sleep_state)
> static int device_suspend_noirq(struct device *dev, pm_message_t state)
> {
> int error = 0;
> + ktime_t starttime = ktime_get();
>
> if (!dev->bus)
> return 0;
> @@ -590,6 +622,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
> if (dev->bus->pm) {
> pm_dev_dbg(dev, state, "LATE ");
> error = pm_noirq_op(dev, dev->bus->pm, state);
> + device_show_time(dev, starttime, state, "late");
> }
> return error;
> }
> @@ -631,6 +664,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
> static int device_suspend(struct device *dev, pm_message_t state)
> {
> int error = 0;
> + ktime_t starttime = ktime_get();
>
> down(&dev->sem);
>
> @@ -666,6 +700,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
> suspend_report_result(dev->bus->suspend, error);
> }
> }
> + device_show_time(dev, starttime, state, NULL);
> End:
> up(&dev->sem);
>
You introduce what appears to be a new CONFIG_ option but do not
introduce a Kconfig fragment to create it? Where did that go?
-apw
More information about the kernel-team
mailing list