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

[Manoj Iyer]

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