Linux Archive

Linux Archive (http://www.linux-archive.org/)
-   Ubuntu Kernel Team (http://www.linux-archive.org/ubuntu-kernel-team/)
-   -   PM: Measure device suspend and resume times (http://www.linux-archive.org/ubuntu-kernel-team/314509-pm-measure-device-suspend-resume-times.html)

Rafael J. Wysocki 12-17-2009 11:57 PM

PM: Measure device suspend and resume times
 
Measure and print the time of suspending and resuming all devices.

Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
(cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)

Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com>
---
drivers/base/power/main.c | 27 +++++++++++++++++++++++++++
1 files changed, 27 insertions(+), 0 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 8aa2443..d72d4b3 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -324,6 +324,23 @@ 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 dpm_show_time(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;
+ pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs
",
+ info ?: "", info ? " " : "", pm_verb(state.event),
+ usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
+}
+
/*------------------------- Resume routines -------------------------*/

/**
@@ -363,6 +380,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
void dpm_resume_noirq(pm_message_t state)
{
struct device *dev;
+ ktime_t starttime = ktime_get();

mutex_lock(&dpm_list_mtx);
transition_started = false;
@@ -376,6 +394,7 @@ void dpm_resume_noirq(pm_message_t state)
pm_dev_err(dev, state, " early", error);
}
mutex_unlock(&dpm_list_mtx);
+ dpm_show_time(starttime, state, "early");
resume_device_irqs();
}
EXPORT_SYMBOL_GPL(dpm_resume_noirq);
@@ -441,6 +460,7 @@ static int device_resume(struct device *dev, pm_message_t state)
static void dpm_resume(pm_message_t state)
{
struct list_head list;
+ ktime_t starttime = ktime_get();

INIT_LIST_HEAD(&list);
mutex_lock(&dpm_list_mtx);
@@ -469,6 +489,7 @@ static void dpm_resume(pm_message_t state)
}
list_splice(&list, &dpm_list);
mutex_unlock(&dpm_list_mtx);
+ dpm_show_time(starttime, state, NULL);
}

/**
@@ -604,6 +625,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
int dpm_suspend_noirq(pm_message_t state)
{
struct device *dev;
+ ktime_t starttime = ktime_get();
int error = 0;

suspend_device_irqs();
@@ -619,6 +641,8 @@ int dpm_suspend_noirq(pm_message_t state)
mutex_unlock(&dpm_list_mtx);
if (error)
dpm_resume_noirq(resume_event(state));
+ else
+ dpm_show_time(starttime, state, "late");
return error;
}
EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
@@ -679,6 +703,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
static int dpm_suspend(pm_message_t state)
{
struct list_head list;
+ ktime_t starttime = ktime_get();
int error = 0;

INIT_LIST_HEAD(&list);
@@ -704,6 +729,8 @@ static int dpm_suspend(pm_message_t state)
}
list_splice(&list, dpm_list.prev);
mutex_unlock(&dpm_list_mtx);
+ if (!error)
+ dpm_show_time(starttime, state, NULL);
return error;
}

--
1.6.3.3



Cheers
--- manjo

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Rafael J. Wysocki 12-17-2009 11:57 PM

PM: Measure device suspend and resume times
 
Measure and print the time of suspending and resuming all devices.

Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
(cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)

Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com>
---
drivers/base/power/main.c | 27 +++++++++++++++++++++++++++
1 files changed, 27 insertions(+), 0 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 8aa2443..d72d4b3 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -324,6 +324,23 @@ 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 dpm_show_time(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;
+ pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs
",
+ info ?: "", info ? " " : "", pm_verb(state.event),
+ usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
+}
+
/*------------------------- Resume routines -------------------------*/

/**
@@ -363,6 +380,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
void dpm_resume_noirq(pm_message_t state)
{
struct device *dev;
+ ktime_t starttime = ktime_get();

mutex_lock(&dpm_list_mtx);
transition_started = false;
@@ -376,6 +394,7 @@ void dpm_resume_noirq(pm_message_t state)
pm_dev_err(dev, state, " early", error);
}
mutex_unlock(&dpm_list_mtx);
+ dpm_show_time(starttime, state, "early");
resume_device_irqs();
}
EXPORT_SYMBOL_GPL(dpm_resume_noirq);
@@ -441,6 +460,7 @@ static int device_resume(struct device *dev, pm_message_t state)
static void dpm_resume(pm_message_t state)
{
struct list_head list;
+ ktime_t starttime = ktime_get();

INIT_LIST_HEAD(&list);
mutex_lock(&dpm_list_mtx);
@@ -469,6 +489,7 @@ static void dpm_resume(pm_message_t state)
}
list_splice(&list, &dpm_list);
mutex_unlock(&dpm_list_mtx);
+ dpm_show_time(starttime, state, NULL);
}

/**
@@ -604,6 +625,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
int dpm_suspend_noirq(pm_message_t state)
{
struct device *dev;
+ ktime_t starttime = ktime_get();
int error = 0;

suspend_device_irqs();
@@ -619,6 +641,8 @@ int dpm_suspend_noirq(pm_message_t state)
mutex_unlock(&dpm_list_mtx);
if (error)
dpm_resume_noirq(resume_event(state));
+ else
+ dpm_show_time(starttime, state, "late");
return error;
}
EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
@@ -679,6 +703,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
static int dpm_suspend(pm_message_t state)
{
struct list_head list;
+ ktime_t starttime = ktime_get();
int error = 0;

INIT_LIST_HEAD(&list);
@@ -704,6 +729,8 @@ static int dpm_suspend(pm_message_t state)
}
list_splice(&list, dpm_list.prev);
mutex_unlock(&dpm_list_mtx);
+ if (!error)
+ dpm_show_time(starttime, state, NULL);
return error;
}

--
1.6.3.3


Cheers
--- manjo

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Manoj Iyer 01-25-2010 12:05 AM

PM: Measure device suspend and resume times
 
The following patch from Rafael measures the suspend/resume times of
devices. It logs the total suspend/resume times of devices as follows:

[ 62.820296] PM: suspend of devices complete after 2108.836 msecs
[ 62.820300] PM: suspend devices took 2.110 seconds
[ 62.860107] PM: late suspend of devices complete after 39.801 msecs
[ 63.440105] PM: early resume of devices complete after 20.013 msecs
[ 67.337821] PM: resume of devices complete after 3887.665 msecs
[ 67.338078] PM: resume devices took 3.890 seconds
[ 67.338117] PM: Finishing wakeup.


The following changes since commit
8275e80fb72b97750d338c905ed7575df8967b95:
Rafael J. Wysocki (1):
PM: Measure device suspend and resume times

are available in the git repository at:


ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git
suspendresume

Andy Whitcroft 01-25-2010 12:35 PM

PM: Measure device suspend and resume times
 
On Sun, Jan 24, 2010 at 07:05:53PM -0600, Manoj Iyer wrote:
>
> The following patch from Rafael measures the suspend/resume times of
> devices. It logs the total suspend/resume times of devices as follows:
>
> [ 62.820296] PM: suspend of devices complete after 2108.836 msecs
> [ 62.820300] PM: suspend devices took 2.110 seconds
> [ 62.860107] PM: late suspend of devices complete after 39.801 msecs
> [ 63.440105] PM: early resume of devices complete after 20.013 msecs
> [ 67.337821] PM: resume of devices complete after 3887.665 msecs
> [ 67.338078] PM: resume devices took 3.890 seconds
> [ 67.338117] PM: Finishing wakeup.

How does this help us above and beyond the counts we already have? In
karmic and lucid we already get these:

[55841.240147] PM: suspend devices took 1.500 seconds
[55845.696481] PM: resume devices took 3.850 seconds

It looks to my eye all I am getting from this patch is the late suspend
and early resume numbers? Are these useful enough to warrent patching?
What do they represent?

Convince me :)

-apw

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Colin Ian King 01-25-2010 02:01 PM

PM: Measure device suspend and resume times
 
Maybe I'm missing something, but it would be even more useful to get the
resume time of each device so that we can see where resume bottlenecks
are occurring. I'd like to know which device is causing the hangs.

Colin

On Sun, 2010-01-24 at 19:05 -0600, Manoj Iyer wrote:
> The following patch from Rafael measures the suspend/resume times of
> devices. It logs the total suspend/resume times of devices as follows:
>
> [ 62.820296] PM: suspend of devices complete after 2108.836 msecs
> [ 62.820300] PM: suspend devices took 2.110 seconds
> [ 62.860107] PM: late suspend of devices complete after 39.801 msecs
> [ 63.440105] PM: early resume of devices complete after 20.013 msecs
> [ 67.337821] PM: resume of devices complete after 3887.665 msecs
> [ 67.338078] PM: resume devices took 3.890 seconds
> [ 67.338117] PM: Finishing wakeup.
>
>
> The following changes since commit
> 8275e80fb72b97750d338c905ed7575df8967b95:
> Rafael J. Wysocki (1):
> PM: Measure device suspend and resume times
>
> are available in the git repository at:
>
>
> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git
> suspendresume
>
> From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001
> From: Rafael J. Wysocki <rjw@sisk.pl>
> Date: Fri, 18 Dec 2009 01:57:47 +0100
> Subject: [PATCH] PM: Measure device suspend and resume times
>
> Measure and print the time of suspending and resuming all devices.
>
> Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)
>
> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com>
> ---
> drivers/base/power/main.c | 27 +++++++++++++++++++++++++++
> 1 files changed, 27 insertions(+), 0 deletions(-)
>
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 8aa2443..d72d4b3 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -324,6 +324,23 @@ 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 dpm_show_time(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;
> + pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs
",
> + info ?: "", info ? " " : "", pm_verb(state.event),
> + usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
> +}
> +
> /*------------------------- Resume routines -------------------------*/
>
> /**
> @@ -363,6 +380,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
> void dpm_resume_noirq(pm_message_t state)
> {
> struct device *dev;
> + ktime_t starttime = ktime_get();
>
> mutex_lock(&dpm_list_mtx);
> transition_started = false;
> @@ -376,6 +394,7 @@ void dpm_resume_noirq(pm_message_t state)
> pm_dev_err(dev, state, " early", error);
> }
> mutex_unlock(&dpm_list_mtx);
> + dpm_show_time(starttime, state, "early");
> resume_device_irqs();
> }
> EXPORT_SYMBOL_GPL(dpm_resume_noirq);
> @@ -441,6 +460,7 @@ static int device_resume(struct device *dev, pm_message_t state)
> static void dpm_resume(pm_message_t state)
> {
> struct list_head list;
> + ktime_t starttime = ktime_get();
>
> INIT_LIST_HEAD(&list);
> mutex_lock(&dpm_list_mtx);
> @@ -469,6 +489,7 @@ static void dpm_resume(pm_message_t state)
> }
> list_splice(&list, &dpm_list);
> mutex_unlock(&dpm_list_mtx);
> + dpm_show_time(starttime, state, NULL);
> }
>
> /**
> @@ -604,6 +625,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
> int dpm_suspend_noirq(pm_message_t state)
> {
> struct device *dev;
> + ktime_t starttime = ktime_get();
> int error = 0;
>
> suspend_device_irqs();
> @@ -619,6 +641,8 @@ int dpm_suspend_noirq(pm_message_t state)
> mutex_unlock(&dpm_list_mtx);
> if (error)
> dpm_resume_noirq(resume_event(state));
> + else
> + dpm_show_time(starttime, state, "late");
> return error;
> }
> EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
> @@ -679,6 +703,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
> static int dpm_suspend(pm_message_t state)
> {
> struct list_head list;
> + ktime_t starttime = ktime_get();
> int error = 0;
>
> INIT_LIST_HEAD(&list);
> @@ -704,6 +729,8 @@ static int dpm_suspend(pm_message_t state)
> }
> list_splice(&list, dpm_list.prev);
> mutex_unlock(&dpm_list_mtx);
> + if (!error)
> + dpm_show_time(starttime, state, NULL);
> return error;
> }
>
> --
> 1.6.3.3
>
>
>
> Cheers
> --- manjo
>



--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Amit Kucheria 01-26-2010 07:26 AM

PM: Measure device suspend and resume times
 
On 10 Jan 24, Manoy Iyer wrote:
>
> The following patch from Rafael measures the suspend/resume times of
> devices. It logs the total suspend/resume times of devices as follows:
>
> [ 62.820296] PM: suspend of devices complete after 2108.836 msecs
> [ 62.820300] PM: suspend devices took 2.110 seconds
> [ 62.860107] PM: late suspend of devices complete after 39.801 msecs
> [ 63.440105] PM: early resume of devices complete after 20.013 msecs
> [ 67.337821] PM: resume of devices complete after 3887.665 msecs
> [ 67.338078] PM: resume devices took 3.890 seconds
> [ 67.338117] PM: Finishing wakeup.
>
>
> The following changes since commit
> 8275e80fb72b97750d338c905ed7575df8967b95:
> Rafael J. Wysocki (1):
> PM: Measure device suspend and resume times
>
> are available in the git repository at:
>
>
> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git
> suspendresume
>
> From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001
> From: Rafael J. Wysocki <rjw@sisk.pl>
> Date: Fri, 18 Dec 2009 01:57:47 +0100
> Subject: [PATCH] PM: Measure device suspend and resume times
>
> Measure and print the time of suspending and resuming all devices.
>
> Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)
>
> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com>
> ---
> drivers/base/power/main.c | 27 +++++++++++++++++++++++++++
> 1 files changed, 27 insertions(+), 0 deletions(-)
>
> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
> index 8aa2443..d72d4b3 100644
> --- a/drivers/base/power/main.c
> +++ b/drivers/base/power/main.c
> @@ -324,6 +324,23 @@ 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 dpm_show_time(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;
> + pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs
",
> + info ?: "", info ? " " : "", pm_verb(state.event),
> + usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
> +}
> +
> /*------------------------- Resume routines -------------------------*/
>
> /**
> @@ -363,6 +380,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
> void dpm_resume_noirq(pm_message_t state)
> {
> struct device *dev;
> + ktime_t starttime = ktime_get();
>
> mutex_lock(&dpm_list_mtx);
> transition_started = false;
> @@ -376,6 +394,7 @@ void dpm_resume_noirq(pm_message_t state)
> pm_dev_err(dev, state, " early", error);
> }
> mutex_unlock(&dpm_list_mtx);
> + dpm_show_time(starttime, state, "early");
> resume_device_irqs();
> }
> EXPORT_SYMBOL_GPL(dpm_resume_noirq);
> @@ -441,6 +460,7 @@ static int device_resume(struct device *dev, pm_message_t state)
> static void dpm_resume(pm_message_t state)
> {
> struct list_head list;
> + ktime_t starttime = ktime_get();
>
> INIT_LIST_HEAD(&list);
> mutex_lock(&dpm_list_mtx);
> @@ -469,6 +489,7 @@ static void dpm_resume(pm_message_t state)
> }
> list_splice(&list, &dpm_list);
> mutex_unlock(&dpm_list_mtx);
> + dpm_show_time(starttime, state, NULL);
> }
>
> /**
> @@ -604,6 +625,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
> int dpm_suspend_noirq(pm_message_t state)
> {
> struct device *dev;
> + ktime_t starttime = ktime_get();
> int error = 0;
>
> suspend_device_irqs();
> @@ -619,6 +641,8 @@ int dpm_suspend_noirq(pm_message_t state)
> mutex_unlock(&dpm_list_mtx);
> if (error)
> dpm_resume_noirq(resume_event(state));
> + else
> + dpm_show_time(starttime, state, "late");
> return error;
> }
> EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
> @@ -679,6 +703,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
> static int dpm_suspend(pm_message_t state)
> {
> struct list_head list;
> + ktime_t starttime = ktime_get();
> int error = 0;
>
> INIT_LIST_HEAD(&list);
> @@ -704,6 +729,8 @@ static int dpm_suspend(pm_message_t state)
> }
> list_splice(&list, dpm_list.prev);
> mutex_unlock(&dpm_list_mtx);
> + if (!error)
> + dpm_show_time(starttime, state, NULL);
> return error;
> }
>
> --
> 1.6.3.3
>
>
>
> Cheers
> --- manjo

It seems to me that this patch enables the extra logging unconditionally. Is
that true? Or does it require PM_DEBUG to be enabled?

/Amit

--
----------------------------------------------------------------------
Amit Kucheria, Kernel Engineer || amit.kucheria@canonical.com
----------------------------------------------------------------------

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

01-26-2010 01:38 PM

PM: Measure device suspend and resume times
 
Yes, I do have a patch for that, but I not sure we want to have that in
Lucid kernel as it populates dmesg with a ton of info.


Cheers
--- manjo

On Mon, 25 Jan 2010, Colin Ian King wrote:

> Maybe I'm missing something, but it would be even more useful to get the
> resume time of each device so that we can see where resume bottlenecks
> are occurring. I'd like to know which device is causing the hangs.
>
> Colin
>
> On Sun, 2010-01-24 at 19:05 -0600, Manoj Iyer wrote:
>> The following patch from Rafael measures the suspend/resume times of
>> devices. It logs the total suspend/resume times of devices as follows:
>>
>> [ 62.820296] PM: suspend of devices complete after 2108.836 msecs
>> [ 62.820300] PM: suspend devices took 2.110 seconds
>> [ 62.860107] PM: late suspend of devices complete after 39.801 msecs
>> [ 63.440105] PM: early resume of devices complete after 20.013 msecs
>> [ 67.337821] PM: resume of devices complete after 3887.665 msecs
>> [ 67.338078] PM: resume devices took 3.890 seconds
>> [ 67.338117] PM: Finishing wakeup.
>>
>>
>> The following changes since commit
>> 8275e80fb72b97750d338c905ed7575df8967b95:
>> Rafael J. Wysocki (1):
>> PM: Measure device suspend and resume times
>>
>> are available in the git repository at:
>>
>>
>> ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git
>> suspendresume
>>
>> From 8275e80fb72b97750d338c905ed7575df8967b95 Mon Sep 17 00:00:00 2001
>> From: Rafael J. Wysocki <rjw@sisk.pl>
>> Date: Fri, 18 Dec 2009 01:57:47 +0100
>> Subject: [PATCH] PM: Measure device suspend and resume times
>>
>> Measure and print the time of suspending and resuming all devices.
>>
>> Signed-off-by: Rafael J. Wysocki <rjw@sisk.pl>
>> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)
>>
>> Signed-off-by: Manoj Iyer <manoj.iyer@canonical.com>
>> ---
>> drivers/base/power/main.c | 27 +++++++++++++++++++++++++++
>> 1 files changed, 27 insertions(+), 0 deletions(-)
>>
>> diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
>> index 8aa2443..d72d4b3 100644
>> --- a/drivers/base/power/main.c
>> +++ b/drivers/base/power/main.c
>> @@ -324,6 +324,23 @@ 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 dpm_show_time(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;
>> + pr_info("PM: %s%s%s of devices complete after %ld.%03ld msecs
",
>> + info ?: "", info ? " " : "", pm_verb(state.event),
>> + usecs / USEC_PER_MSEC, usecs % USEC_PER_MSEC);
>> +}
>> +
>> /*------------------------- Resume routines -------------------------*/
>>
>> /**
>> @@ -363,6 +380,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state)
>> void dpm_resume_noirq(pm_message_t state)
>> {
>> struct device *dev;
>> + ktime_t starttime = ktime_get();
>>
>> mutex_lock(&dpm_list_mtx);
>> transition_started = false;
>> @@ -376,6 +394,7 @@ void dpm_resume_noirq(pm_message_t state)
>> pm_dev_err(dev, state, " early", error);
>> }
>> mutex_unlock(&dpm_list_mtx);
>> + dpm_show_time(starttime, state, "early");
>> resume_device_irqs();
>> }
>> EXPORT_SYMBOL_GPL(dpm_resume_noirq);
>> @@ -441,6 +460,7 @@ static int device_resume(struct device *dev, pm_message_t state)
>> static void dpm_resume(pm_message_t state)
>> {
>> struct list_head list;
>> + ktime_t starttime = ktime_get();
>>
>> INIT_LIST_HEAD(&list);
>> mutex_lock(&dpm_list_mtx);
>> @@ -469,6 +489,7 @@ static void dpm_resume(pm_message_t state)
>> }
>> list_splice(&list, &dpm_list);
>> mutex_unlock(&dpm_list_mtx);
>> + dpm_show_time(starttime, state, NULL);
>> }
>>
>> /**
>> @@ -604,6 +625,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state)
>> int dpm_suspend_noirq(pm_message_t state)
>> {
>> struct device *dev;
>> + ktime_t starttime = ktime_get();
>> int error = 0;
>>
>> suspend_device_irqs();
>> @@ -619,6 +641,8 @@ int dpm_suspend_noirq(pm_message_t state)
>> mutex_unlock(&dpm_list_mtx);
>> if (error)
>> dpm_resume_noirq(resume_event(state));
>> + else
>> + dpm_show_time(starttime, state, "late");
>> return error;
>> }
>> EXPORT_SYMBOL_GPL(dpm_suspend_noirq);
>> @@ -679,6 +703,7 @@ static int device_suspend(struct device *dev, pm_message_t state)
>> static int dpm_suspend(pm_message_t state)
>> {
>> struct list_head list;
>> + ktime_t starttime = ktime_get();
>> int error = 0;
>>
>> INIT_LIST_HEAD(&list);
>> @@ -704,6 +729,8 @@ static int dpm_suspend(pm_message_t state)
>> }
>> list_splice(&list, dpm_list.prev);
>> mutex_unlock(&dpm_list_mtx);
>> + if (!error)
>> + dpm_show_time(starttime, state, NULL);
>> return error;
>> }
>>
>> --
>> 1.6.3.3
>>
>>
>>
>> Cheers
>> --- manjo
>>
>
>
>

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Jeremy Kerr 01-26-2010 11:05 PM

PM: Measure device suspend and resume times
 
Hi Manjom

> Yes, I do have a patch for that, but I not sure we want to have that in
> Lucid kernel as it populates dmesg with a ton of info.

Perhaps we could do this with tracepoints, which should have very little
overhead (and not pollute dmesg) when we're not tracing.

Do you want me to put a patch together?

Cheers,


Jeremy

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

01-27-2010 05:54 AM

PM: Measure device suspend and resume times
 
Jeremy,

There is a generate_resume_trace() in trace.c under
drivers/base/power/trace.c, but it did not look like it generated what I
was looking for.

Cheers
--- manjo

On Wed, 27 Jan 2010, Jeremy Kerr wrote:

> Hi Manjom
>
>> Yes, I do have a patch for that, but I not sure we want to have that in
>> Lucid kernel as it populates dmesg with a ton of info.
>
> Perhaps we could do this with tracepoints, which should have very little
> overhead (and not pollute dmesg) when we're not tracing.
>
> Do you want me to put a patch together?
>
> Cheers,
>
>
> Jeremy
>

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team

Andy Whitcroft 01-27-2010 10:12 AM

PM: Measure device suspend and resume times
 
On Tue, Jan 26, 2010 at 01:56:04PM +0530, Amit Kucheria wrote:

> It seems to me that this patch enables the extra logging unconditionally. Is
> that true? Or does it require PM_DEBUG to be enabled?

The original is unconditional but only adds two lines of additional
output to a suspend/resume. Though I am not sure its adding anything to
the data we have.

I suspect we need a modified version of the 'per device' data which can
be turned on somehow when we have an issue.

-apw

--
kernel-team mailing list
kernel-team@lists.ubuntu.com
https://lists.ubuntu.com/mailman/listinfo/kernel-team


All times are GMT. The time now is 07:41 AM.

VBulletin, Copyright ©2000 - 2014, Jelsoft Enterprises Ltd.
Content Relevant URLs by vBSEO ©2007, Crawlability, Inc.