From patchwork Wed Jul 17 23:03:21 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Shuah Khan X-Patchwork-Id: 2829122 Return-Path: X-Original-To: patchwork-linux-pm@patchwork.kernel.org Delivered-To: patchwork-parsemail@patchwork1.web.kernel.org Received: from mail.kernel.org (mail.kernel.org [198.145.19.201]) by patchwork1.web.kernel.org (Postfix) with ESMTP id B31F49F967 for ; Wed, 17 Jul 2013 23:03:32 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 8CAB320418 for ; Wed, 17 Jul 2013 23:03:31 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 0D8BF20414 for ; Wed, 17 Jul 2013 23:03:30 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757840Ab3GQXD3 (ORCPT ); Wed, 17 Jul 2013 19:03:29 -0400 Received: from qmta05.emeryville.ca.mail.comcast.net ([76.96.30.48]:53219 "EHLO qmta05.emeryville.ca.mail.comcast.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1757508Ab3GQXD1 (ORCPT ); Wed, 17 Jul 2013 19:03:27 -0400 Received: from omta12.emeryville.ca.mail.comcast.net ([76.96.30.44]) by qmta05.emeryville.ca.mail.comcast.net with comcast id 1aPc1m0060x6nqcA5b3TG4; Wed, 17 Jul 2013 23:03:27 +0000 Received: from mail.gonehiking.org ([50.134.149.16]) by omta12.emeryville.ca.mail.comcast.net with comcast id 1b3Q1m00T0MU7Qa8Yb3Q5h; Wed, 17 Jul 2013 23:03:26 +0000 Received: from orthanc.internal (orthanc.internal [192.168.1.24]) by mail.gonehiking.org (Postfix) with ESMTP id 5CABD80B2C; Wed, 17 Jul 2013 17:03:27 -0600 (MDT) From: Shuah Khan To: len.brown@intel.com, pavel@ucw.cz, rjw@sisk.pl, gregkh@linuxfoundation.org, rostedt@goodmis.org, fweisbec@gmail.com, mingo@redhat.com, paul.gortmaker@windriver.com, joe@perches.com Cc: Shuah Khan , linux-pm@vger.kernel.org, linux-kernel@vger.kernel.org, shuahkhan@gmail.com Subject: [PATCH v3] power: new trace event to print device suspend and resume time Date: Wed, 17 Jul 2013 17:03:21 -0600 Message-Id: <1374102201-2937-1-git-send-email-shuah.kh@samsung.com> X-Mailer: git-send-email 1.7.10.4 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=comcast.net; s=q20121106; t=1374102207; bh=7wOIHp+70tGoQllNO5Ie5NJE7OxE0QiZOppIrWLhvME=; h=Received:Received:Received:From:To:Subject:Date:Message-Id; b=Pc/bkDYqWMfVbvg4J/kUdRK7iKyXlsG31lwrJu6MXHdyc5XRHJFdqg3h/aSoPR+7R IBDL9ywSpnS2QJ0l6c67MRPPkEYJ8ZBfMoHdGGjioFsCjpPdw7xAmVOceg+jq6RixR uI+dgvoeFICL6sGQRVQnTNyta/Pd88eu9ysrwS3/x8Bq0bXcAqhujmf5P17WpKgTA0 rVBBazik3+YWH5gAhbyt/q0oXvl8GxgwMp4f9aot4LmGwIT8eMAoCXQXHpr38SeKUc 7DVeQwTe4I7oSRtdnYStzA3fPo3tTXb1gWxPLN7DrqAFiaMCkq73DWiOul2/HNXDFR C+fjyVhLJmfVw== Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Spam-Status: No, score=-7.2 required=5.0 tests=BAYES_00,DKIM_SIGNED, RCVD_IN_DNSWL_HI,RP_MATCHES_RCVD,T_DKIM_INVALID,UNPARSEABLE_RELAY autolearn=unavailable version=3.3.1 X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on mail.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP A new trace event is added to pm events to print time it takes to suspend and resume a device. It generates trace message that includes device, driver, parent information in addition to the type of pm ops invoked as well as the pm event and error status from the pm ops. Example trace below: bash-2239 [000] .... 290.883035: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class nsecs=332 err=0 bash-2239 [000] .... 290.883041: device_pm_report_time: rfkill rf kill3 parent=phy0 state=freeze ops=legacy class nsecs=216 err=0 bash-2239 [001] .... 290.973892: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=freeze ops=legacy class nsecs=90846477 err=0 bash-2239 [001] .... 293.660129: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=restore ops=legacy class nsecs=101295162 err=0 bash-2239 [001] .... 293.660147: device_pm_report_time: rfkill rfkill3 parent=phy0 state=restore ops=legacy class nsecs=1804 err=0 bash-2239 [001] .... 293.660157: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class nsecs=757 err=0 Signed-off-by: Shuah Khan --- drivers/base/power/main.c | 29 +++++++++++++++++++++-------- include/trace/events/power.h | 35 +++++++++++++++++++++++++++++++++++ 2 files changed, 56 insertions(+), 8 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..63c58d7 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -28,6 +28,7 @@ #include #include #include +#include #include #include "../base.h" #include "power.h" @@ -56,6 +57,8 @@ static pm_message_t pm_transition; static int async_error; +static char *pm_verb(int); + /** * device_pm_sleep_init - Initialize system suspend-related device fields. * @dev: Device object being initialized. @@ -172,16 +175,23 @@ static ktime_t initcall_debug_start(struct device *dev) } static void initcall_debug_report(struct device *dev, ktime_t calltime, - int error) + int error, pm_message_t state, char *info) { ktime_t delta, rettime; + rettime = ktime_get(); + delta = ktime_sub(rettime, calltime); + if (pm_print_times_enabled) { - rettime = ktime_get(); - delta = ktime_sub(rettime, calltime); pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev), error, (unsigned long long)ktime_to_ns(delta) >> 10); } + + trace_device_pm_report_time(dev_name(dev), dev_driver_string(dev), + dev->parent ? dev_name(dev->parent) : "none", + info ? info : "none ", + (s64) ktime_to_ns(delta), pm_verb(state.event), + error); } /** @@ -379,7 +389,7 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev, error = cb(dev); suspend_report_result(cb, error); - initcall_debug_report(dev, calltime, error); + initcall_debug_report(dev, calltime, error, state, info); return error; } @@ -1027,7 +1037,8 @@ EXPORT_SYMBOL_GPL(dpm_suspend_end); * @cb: Suspend callback to execute. */ static int legacy_suspend(struct device *dev, pm_message_t state, - int (*cb)(struct device *dev, pm_message_t state)) + int (*cb)(struct device *dev, pm_message_t state), + char *info) { int error; ktime_t calltime; @@ -1037,7 +1048,7 @@ static int legacy_suspend(struct device *dev, pm_message_t state, error = cb(dev, state); suspend_report_result(cb, error); - initcall_debug_report(dev, calltime, error); + initcall_debug_report(dev, calltime, error, state, info); return error; } @@ -1097,7 +1108,8 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async) goto Run; } else if (dev->class->suspend) { pm_dev_dbg(dev, state, "legacy class "); - error = legacy_suspend(dev, state, dev->class->suspend); + error = legacy_suspend(dev, state, dev->class->suspend, + "legacy class "); goto End; } } @@ -1108,7 +1120,8 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async) callback = pm_op(dev->bus->pm, state); } else if (dev->bus->suspend) { pm_dev_dbg(dev, state, "legacy bus "); - error = legacy_suspend(dev, state, dev->bus->suspend); + error = legacy_suspend(dev, state, dev->bus->suspend, + "legacy bus "); goto End; } } diff --git a/include/trace/events/power.h b/include/trace/events/power.h index 8e42410..24afd22 100644 --- a/include/trace/events/power.h +++ b/include/trace/events/power.h @@ -66,6 +66,41 @@ TRACE_EVENT(machine_suspend, TP_printk("state=%lu", (unsigned long)__entry->state) ); +TRACE_EVENT(device_pm_report_time, + + TP_PROTO(const char *device, const char *driver, const char *parent, + const char *pm_ops, s64 ops_time, char *pm_event_str, + int error), + + TP_ARGS(device, driver, parent, pm_ops, ops_time, pm_event_str, error), + + TP_STRUCT__entry( + __string(device, device) + __string(driver, driver) + __string(parent, parent) + __string(pm_ops, pm_ops) + __string(pm_event_str, pm_event_str) + __field(s64, ops_time) + __field(int, error) + ), + + TP_fast_assign( + __assign_str(device, device); + __assign_str(driver, driver); + __assign_str(parent, parent); + __assign_str(pm_ops, pm_ops); + __assign_str(pm_event_str, pm_event_str); + __entry->ops_time = ops_time; + __entry->error = error; + ), + + /* ops_str has an extra space at the end */ + TP_printk("%s %s parent=%s state=%s ops=%snsecs=%lld err=%d", + __get_str(driver), __get_str(device), __get_str(parent), + __get_str(pm_event_str), __get_str(pm_ops), + __entry->ops_time, __entry->error) +); + DECLARE_EVENT_CLASS(wakeup_source, TP_PROTO(const char *name, unsigned int state),