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

[Colin Ian King]

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 at 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 at sisk.pl>
> (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899)
> 
> Signed-off-by: Manoj Iyer <manoj.iyer at 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
>