From patchwork Fri Jul 19 18:27:20 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Shuah Khan X-Patchwork-Id: 2830665 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 F27D89F4D5 for ; Fri, 19 Jul 2013 18:27:35 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id A7DC02025D for ; Fri, 19 Jul 2013 18:27:34 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 3393F20221 for ; Fri, 19 Jul 2013 18:27:33 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1760978Ab3GSS1c (ORCPT ); Fri, 19 Jul 2013 14:27:32 -0400 Received: from qmta02.emeryville.ca.mail.comcast.net ([76.96.30.24]:39397 "EHLO qmta02.emeryville.ca.mail.comcast.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1760873Ab3GSS1b (ORCPT ); Fri, 19 Jul 2013 14:27:31 -0400 Received: from omta24.emeryville.ca.mail.comcast.net ([76.96.30.92]) by qmta02.emeryville.ca.mail.comcast.net with comcast id 2Gay1m0021zF43QA2JTXFY; Fri, 19 Jul 2013 18:27:31 +0000 Received: from mail.gonehiking.org ([50.134.149.16]) by omta24.emeryville.ca.mail.comcast.net with comcast id 2JTU1m00N0MU7Qa8kJTUxT; Fri, 19 Jul 2013 18:27:30 +0000 Received: from orthanc.internal (orthanc.internal [192.168.1.24]) by mail.gonehiking.org (Postfix) with ESMTP id 1DD5A802EE; Fri, 19 Jul 2013 12:27:34 -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 v6] power: new trace event to print device suspend and resume time Date: Fri, 19 Jul 2013 12:27:20 -0600 Message-Id: <1374258440-7152-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=1374258451; bh=bwrCFonHZkyWR9v4GmiE1mVIwQkixgBuezYjKVbLZZM=; h=Received:Received:Received:From:To:Subject:Date:Message-Id; b=lURPkSWDe4bh3Ni5v05WIi3hfAgBNcRZMjse/2QBWDV8PR7DOHqqETbLSfPLx37En V3iWU2uvNMuAL49iYVIZp1DlmR/r6uzM7rPHt5ZbC0tZg7eZDgz1nJ30+7nfhxwtt6 0uhMakyLLnJBLfzp5mGasi58YYiQIxt1SRgCQs4+ZtvLCqK471Bf6pp1U09XFNLSwK jcOpNTW1jNo/HsALg+usuIOx3kvGbyDgdvFm4ZwVWNermobZlf88N9J9W0abadZP3r FCvW7rCPuZ4O5naAYWjgeKMtjGghWmsYiDo/EYoVJPMw1FrO8k0DvtuMj0aSTkOlD7 FpfqzXkJzNJmw== 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-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 | 77 +++++++++++++++++++++++------------------- include/trace/events/power.h | 37 ++++++++++++++++++++ 2 files changed, 80 insertions(+), 34 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..9f098a8 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,30 @@ static pm_message_t pm_transition; static int async_error; +static char *pm_verb(int event) +{ + switch (event) { + case PM_EVENT_SUSPEND: + return "suspend"; + case PM_EVENT_RESUME: + return "resume"; + case PM_EVENT_FREEZE: + return "freeze"; + case PM_EVENT_QUIESCE: + return "quiesce"; + case PM_EVENT_HIBERNATE: + return "hibernate"; + case PM_EVENT_THAW: + return "thaw"; + case PM_EVENT_RESTORE: + return "restore"; + case PM_EVENT_RECOVER: + return "recover"; + default: + return "(unknown PM event)"; + } +} + /** * device_pm_sleep_init - Initialize system suspend-related device fields. * @dev: Device object being initialized. @@ -172,16 +197,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; + ktime_t rettime; + s64 nsecs; + + rettime = ktime_get(); + nsecs = (s64) ktime_to_ns(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); + error, (unsigned long long)nsecs >> 10); } + + trace_device_pm_report_time(dev, info, nsecs, pm_verb(state.event), + error); } /** @@ -309,30 +339,6 @@ static pm_callback_t pm_noirq_op(const struct dev_pm_ops *ops, pm_message_t stat return NULL; } -static char *pm_verb(int event) -{ - switch (event) { - case PM_EVENT_SUSPEND: - return "suspend"; - case PM_EVENT_RESUME: - return "resume"; - case PM_EVENT_FREEZE: - return "freeze"; - case PM_EVENT_QUIESCE: - return "quiesce"; - case PM_EVENT_HIBERNATE: - return "hibernate"; - case PM_EVENT_THAW: - return "thaw"; - case PM_EVENT_RESTORE: - return "restore"; - case PM_EVENT_RECOVER: - return "recover"; - default: - return "(unknown PM event)"; - } -} - static void pm_dev_dbg(struct device *dev, pm_message_t state, char *info) { dev_dbg(dev, "%s%s%s\n", info, pm_verb(state.event), @@ -379,7 +385,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 +1033,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 +1044,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 +1104,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 +1116,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..5d6a208 100644 --- a/include/trace/events/power.h +++ b/include/trace/events/power.h @@ -66,6 +66,43 @@ TRACE_EVENT(machine_suspend, TP_printk("state=%lu", (unsigned long)__entry->state) ); +TRACE_EVENT(device_pm_report_time, + + TP_PROTO(struct device *dev, const char *pm_ops, s64 ops_time, + char *pm_event_str, int error), + + TP_ARGS(dev, pm_ops, ops_time, pm_event_str, error), + + TP_STRUCT__entry( + __string(device, dev_name(dev)) + __string(driver, dev_driver_string(dev)) + __string(parent, dev->parent ? dev_name(dev->parent) : "none") + __string(pm_ops, pm_ops ? pm_ops : "none ") + __string(pm_event_str, pm_event_str) + __field(s64, ops_time) + __field(int, error) + ), + + TP_fast_assign( + char *tmp_p = dev->parent ? dev_name(dev->parent) : "none"; + char *tmp_i = pm_ops ? pm_ops : "none "; + + __assign_str(device, dev_name(dev)); + __assign_str(driver, dev_driver_string(dev)); + __assign_str(parent, tmp_p); + __assign_str(pm_ops, tmp_i); + __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),