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

[Amit Kucheria]

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 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

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 at canonical.com
----------------------------------------------------------------------