Patchwork [LUCID,1/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times.

login
register
mail settings
Submitter Manoj Iyer
Date Feb. 11, 2010, 7:55 p.m.
Message ID <alpine.DEB.2.00.1002111349390.19816@hungry>
Download mbox | patch
Permalink /patch/45143/
State Changes Requested
Delegated to: Andy Whitcroft
Headers show

Comments

Manoj Iyer - Feb. 11, 2010, 7:55 p.m.
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.

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
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@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@canonical.com>
---
  drivers/base/power/main.c |   35 +++++++++++++++++++++++++++++++++++
  1 files changed, 35 insertions(+), 0 deletions(-)
Chase Douglas - Feb. 11, 2010, 8:04 p.m.
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.
> 
> 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
> 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@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@canonical.com>
Acked-by: Chase Douglas <chase.douglas@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
> +
>   /*
>    * 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);
>
Amit Kucheria - Feb. 12, 2010, 9:18 a.m.
On 10 Feb 11, Manoy 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.

So you've taken the patch and modified it some more?

In that case, let's add the patch as-is with Rafael's signoff (or cherry-pick
it from Linus' tree, though I don't see it there yet). Then, add your changes
on top separately.

> 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
> 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 
> +++++++++++++++++++++++++++++
Andy Whitcroft - Feb. 12, 2010, 9:48 a.m.
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@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@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
Manoj Iyer - Feb. 12, 2010, 4:37 p.m.
I had sent Rafael's patch earlier to the list, I will follow what amit, 
cherry pick Rafael's, and merge my changes in and resend it.


Cheers
--- manjo

On Fri, 12 Feb 2010, Andy Whitcroft wrote:

> 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@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@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
>
Amit Kucheria - Feb. 12, 2010, 7:17 p.m.
On 10 Feb 12, Manoy Iyer wrote:
> 
> I had sent Rafael's patch earlier to the list, I will follow what amit, 
> cherry pick Rafael's, and merge my changes in and resend it.

Just to be clear, don't merge your changes into that patch. Make it separate.

Cheers,
Amit
 
> Cheers
> --- manjo
> 
> On Fri, 12 Feb 2010, Andy Whitcroft wrote:
> 
> > 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@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@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
> >
> 
> -- 
> kernel-team mailing list
> kernel-team@lists.ubuntu.com
> https://lists.ubuntu.com/mailman/listinfo/kernel-team

Patch

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
+
  /*
   * 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);