From patchwork Wed Jul 17 15:57:39 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Shuah Khan X-Patchwork-Id: 2828814 Return-Path: X-Original-To: patchwork-linux-pm@patchwork.kernel.org Delivered-To: patchwork-parsemail@patchwork2.web.kernel.org Received: from mail.kernel.org (mail.kernel.org [198.145.19.201]) by patchwork2.web.kernel.org (Postfix) with ESMTP id 995E4C0AB2 for ; Wed, 17 Jul 2013 15:57:51 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 21EC62035A for ; Wed, 17 Jul 2013 15:57:50 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 6AB7F2032D for ; Wed, 17 Jul 2013 15:57:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756161Ab3GQP5r (ORCPT ); Wed, 17 Jul 2013 11:57:47 -0400 Received: from qmta10.emeryville.ca.mail.comcast.net ([76.96.30.17]:43682 "EHLO qmta10.emeryville.ca.mail.comcast.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754176Ab3GQP5q (ORCPT ); Wed, 17 Jul 2013 11:57:46 -0400 Received: from omta02.emeryville.ca.mail.comcast.net ([76.96.30.19]) by qmta10.emeryville.ca.mail.comcast.net with comcast id 1Tjt1m0010QkzPwAATxmBc; Wed, 17 Jul 2013 15:57:46 +0000 Received: from mail.gonehiking.org ([50.134.149.16]) by omta02.emeryville.ca.mail.comcast.net with comcast id 1Txj1m00B0MU7Qa8NTxjDu; Wed, 17 Jul 2013 15:57:45 +0000 Received: from orthanc.internal (orthanc.internal [192.168.1.24]) by mail.gonehiking.org (Postfix) with ESMTP id 524F880A74; Wed, 17 Jul 2013 09:57:45 -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 v2] power: new trace event to print device suspend and resume time Date: Wed, 17 Jul 2013 09:57:39 -0600 Message-Id: <1374076659-3444-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=1374076666; bh=sjAjf5EIHwtutZcYhjSxLI3MrDLTfBY/VM00E45Ukm0=; h=Received:Received:Received:From:To:Subject:Date:Message-Id; b=Lp6t3geFi5MuH0UMXk0ky8UeBQWt89byQZ2SzDn13k/0HrJjZHyLf2YbLM3lA/+xf 6j08hmxy0owREdpK9GdY/17+hgZc+pw4U0RdByworinB4Nurk53dVojKz3alfS5z+/ /G+cY4WcO/S3VP9f5BFFHEGf4SMn5hj1+M5pD83nCgyLKMNDeQBBU3qm0F3QOeGfp6 Q7LWiBtcKrwAtfeIj9FZs593FRMZGzQkHvZpEc4cPBAR5B5sXbmdIeCsjUhEI+2lG2 Ayo7hZXEgC9ofBnPzIxKEqMoTjYrnm0IDlxkUEF0eXterJqdvnEDMSokuw0EQPuUvg 611hT85JlijWw== 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=ham 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-2484 [001] .... 907.330148: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=freeze ops=class usecs=0 err=0 bash-2484 [001] .... 909.906743: device_pm_report_time: backlight acpi_video0 parent=0000:00:02.0 state=restore ops=class usecs=0 err=0 bash-2484 [001] .... 907.330155: device_pm_report_time: rfkill rfkill3 parent=phy0 state=freeze ops=legacy class usecs=0 err=0 bash-2484 [001] .... 909.906739: device_pm_report_time: rfkill rfkill3 parent=phy0 state=restore ops=legacy class usecs=1 err=0 bash-2484 [000] .... 907.389079: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=freeze ops=legacy class usecs=57497 err=0 bash-2484 [001] .... 909.906731: device_pm_report_time: ieee80211 phy0 parent=0000:01:00.0 state=restore ops=legacy class usecs=95119 err=0 Signed-off-by: Shuah Khan --- drivers/base/power/main.c | 27 +++++++++++++++++++-------- include/trace/events/power.h | 34 ++++++++++++++++++++++++++++++++++ 2 files changed, 53 insertions(+), 8 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..d268c45 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,21 @@ 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, delta, pm_verb(state.event), error); } /** @@ -379,7 +387,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 +1035,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 +1046,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 +1106,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 +1118,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..6240541 100644 --- a/include/trace/events/power.h +++ b/include/trace/events/power.h @@ -66,6 +66,40 @@ 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, ktime_t 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 = ktime_to_ns(ops_time) >> 10; + __entry->error = error; + ), + + TP_printk("%s %s parent=%s state=%s ops=%s usecs=%lld err=%d\n", + __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),