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

[manoj.iyer at canonical.com]

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