From patchwork Fri Feb 12 19:32:48 2010 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Manoj Iyer X-Patchwork-Id: 45208 X-Patchwork-Delegate: apw@canonical.com Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Received: from chlorine.canonical.com (chlorine.canonical.com [91.189.94.204]) by ozlabs.org (Postfix) with ESMTP id BE0A7B7C09 for ; Sat, 13 Feb 2010 06:32:41 +1100 (EST) Received: from localhost ([127.0.0.1] helo=chlorine.canonical.com) by chlorine.canonical.com with esmtp (Exim 4.69) (envelope-from ) id 1Ng1Fi-00081L-Cn; Fri, 12 Feb 2010 19:32:34 +0000 Received: from adelie.canonical.com ([91.189.90.139]) by chlorine.canonical.com with esmtp (Exim 4.69) (envelope-from ) id 1Ng1Ff-000812-PE for kernel-team@lists.ubuntu.com; Fri, 12 Feb 2010 19:32:31 +0000 Received: from hutte.canonical.com ([91.189.90.181]) by adelie.canonical.com with esmtp (Exim 4.69 #1 (Debian)) id 1Ng1Ff-0005un-O2 for ; Fri, 12 Feb 2010 19:32:31 +0000 Received: from [70.114.236.114] (helo=hungry.local) by hutte.canonical.com with esmtpsa (TLS-1.0:DHE_RSA_AES_256_CBC_SHA1:32) (Exim 4.69) (envelope-from ) id 1Ng1Ff-0001Is-9R for kernel-team@lists.ubuntu.com; Fri, 12 Feb 2010 19:32:31 +0000 Date: Fri, 12 Feb 2010 13:32:48 -0600 (CST) From: Manoj Iyer To: Ubuntu Kernel Team Subject: UBUNTU: SAUCE: PM report driver and device suspend/resume times. Message-ID: User-Agent: Alpine 2.00 (DEB 1167 2008-08-23) MIME-Version: 1.0 X-BeenThere: kernel-team@lists.ubuntu.com X-Mailman-Version: 2.1.9 Precedence: list Reply-To: Manoj Iyer List-Id: Kernel team discussions List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Sender: kernel-team-bounces@lists.ubuntu.com Errors-To: kernel-team-bounces@lists.ubuntu.com Modified patch as per review comments, I will send out the CONFIG patch as soon as I figure out the right procedure. The following changes since commit baaa7713d6701c4280d54a45fc89369c6945e60b: Rajiv Andrade (1): tpm_tis: TPM_STS_DATA_EXPECT workaround are available in the git repository at: ssh://zinc.canonical.com/srv/kernel.ubuntu.com/git/manjo/ubuntu-lucid.git srtimereport Manoj Iyer (1): UBUNTU: SAUCE: PM report driver and device suspend/resume times. Rafael J. Wysocki (1): PM: Measure device suspend and resume times drivers/base/power/main.c | 33 +++++++++++++++++++++++++++++++++ 1 files changed, 33 insertions(+), 0 deletions(-) From 93ea296b84b6f6ae665c6bb0af596f27a6577297 Mon Sep 17 00:00:00 2001 From: Manoj Iyer Date: Fri, 12 Feb 2010 12:28:25 -0600 Subject: [PATCH 2/2] UBUNTU: SAUCE: PM report driver and device suspend/resume times. Based on a patch from Rafael J. Wysocki. This patch prints suspend/resume information for each driver/device to dmesg. Signed-off-by: Manoj Iyer --- drivers/base/power/main.c | 34 ++++++++++++++++++++-------------- 1 files changed, 20 insertions(+), 14 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index d72d4b3..b6aaafb 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -29,6 +29,13 @@ #include "../base.h" #include "power.h" +/* Set default to 100 msecs */ +#ifdef CONFIG_SR_REPORT_TIME_LIMIT +#define SR_REPORT_TIME_LIMIT CONFIG_SR_REPORT_TIME_LIMIT +#else +#define SR_REPORT_TIME_LIMIT 100 +#endif + /* * The entries in the dpm_list list are in a depth first order, simply * because children are guaranteed to be discovered after parents, and @@ -324,7 +331,7 @@ 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) +static void device_show_time(struct device *dev, ktime_t starttime, pm_message_t state, char *info) { ktime_t calltime; s64 usecs64; @@ -336,9 +343,10 @@ static void dpm_show_time(ktime_t starttime, pm_message_t state, char *info) 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); + if ((usecs / USEC_PER_MSEC) > SR_REPORT_TIME_LIMIT) + pr_info("PM: %s%s%s of drv:%s dev:%s complete after %ld.%03ld msecs\n", info ?: "", info ? " " : "", pm_verb(state.event), + dev_driver_string(dev), dev_name(dev), usecs / USEC_PER_MSEC, + usecs % USEC_PER_MSEC); } /*------------------------- Resume routines -------------------------*/ @@ -354,6 +362,7 @@ static void dpm_show_time(ktime_t starttime, pm_message_t state, char *info) static int device_resume_noirq(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); TRACE_DEVICE(dev); TRACE_RESUME(0); @@ -364,6 +373,7 @@ static int device_resume_noirq(struct device *dev, pm_message_t state) if (dev->bus->pm) { pm_dev_dbg(dev, state, "EARLY "); error = pm_noirq_op(dev, dev->bus->pm, state); + device_show_time(dev, starttime, state, "early"); } End: TRACE_RESUME(error); @@ -380,7 +390,6 @@ 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; @@ -394,7 +403,6 @@ 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); @@ -407,6 +415,7 @@ EXPORT_SYMBOL_GPL(dpm_resume_noirq); static int device_resume(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); TRACE_DEVICE(dev); TRACE_RESUME(0); @@ -443,6 +452,7 @@ static int device_resume(struct device *dev, pm_message_t state) error = dev->class->resume(dev); } } + device_show_time(dev, starttime, state, NULL); End: up(&dev->sem); @@ -460,7 +470,6 @@ 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); @@ -489,7 +498,6 @@ 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 +612,7 @@ static pm_message_t resume_event(pm_message_t sleep_state) static int device_suspend_noirq(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); if (!dev->bus) return 0; @@ -611,6 +620,7 @@ static int device_suspend_noirq(struct device *dev, pm_message_t state) if (dev->bus->pm) { pm_dev_dbg(dev, state, "LATE "); error = pm_noirq_op(dev, dev->bus->pm, state); + device_show_time(dev, starttime, state, "late"); } return error; } @@ -625,7 +635,6 @@ 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(); @@ -641,8 +650,6 @@ 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); @@ -655,6 +662,7 @@ EXPORT_SYMBOL_GPL(dpm_suspend_noirq); static int device_suspend(struct device *dev, pm_message_t state) { int error = 0; + ktime_t starttime = ktime_get(); down(&dev->sem); @@ -690,6 +698,7 @@ static int device_suspend(struct device *dev, pm_message_t state) suspend_report_result(dev->bus->suspend, error); } } + device_show_time(dev, starttime, state, NULL); End: up(&dev->sem); @@ -703,7 +712,6 @@ 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); @@ -729,8 +737,6 @@ 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 From 80ccbc89958661041ec09e13193c1a7cfe53d1f3 Mon Sep 17 00:00:00 2001 From: Rafael J. Wysocki Date: Fri, 18 Dec 2009 01:57:47 +0100 Subject: [PATCH 1/2] PM: Measure device suspend and resume times Measure and print the time of suspending and resuming all devices. Signed-off-by: Rafael J. Wysocki (cherry picked from commit ecf762b2581e12ac761d12a6e4e297c2224aa899) Signed-off-by: Manoj Iyer --- 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; }