Patchwork [LUCID] PM: Measure device suspend and resume times

login
register
mail settings
Submitter Manoj Iyer
Date Jan. 25, 2010, 1:05 a.m.
Message ID <alpine.DEB.2.00.1001241900310.27200@hungry>
Download mbox | patch
Permalink /patch/43609/
State Rejected
Delegated to: Andy Whitcroft
Headers show

Comments

Manoj Iyer - Jan. 25, 2010, 1:05 a.m.
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(-)
Andy Whitcroft - Jan. 25, 2010, 1:35 p.m.
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
Colin King - Jan. 25, 2010, 3:01 p.m.
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\n",
> +		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
>
Amit Kucheria - Jan. 26, 2010, 8:26 a.m.
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\n",
> +		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
Manoj Iyer - Jan. 26, 2010, 2:38 p.m.
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\n",
>> +		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
>>
>
>
>
Jeremy Kerr - Jan. 27, 2010, 12:05 a.m.
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
Manoj Iyer - Jan. 27, 2010, 6:54 a.m.
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
>
Andy Whitcroft - Jan. 27, 2010, 11:12 a.m.
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

Patch

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\n",
+		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;
  }