From patchwork Mon Jun 17 19:36:35 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Shuah Khan X-Patchwork-Id: 2737371 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 54C3EC0AB1 for ; Mon, 17 Jun 2013 19:36:47 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 3AE2A20511 for ; Mon, 17 Jun 2013 19:36:46 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 1FE4D20509 for ; Mon, 17 Jun 2013 19:36:45 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753137Ab3FQTgo (ORCPT ); Mon, 17 Jun 2013 15:36:44 -0400 Received: from qmta12.emeryville.ca.mail.comcast.net ([76.96.27.227]:40324 "EHLO qmta12.emeryville.ca.mail.comcast.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751588Ab3FQTgn (ORCPT ); Mon, 17 Jun 2013 15:36:43 -0400 Received: from omta10.emeryville.ca.mail.comcast.net ([76.96.30.28]) by qmta12.emeryville.ca.mail.comcast.net with comcast id pVZx1l0050cQ2SL01Xcj49; Mon, 17 Jun 2013 19:36:43 +0000 Received: from mail.gonehiking.org ([75.71.126.216]) by omta10.emeryville.ca.mail.comcast.net with comcast id pXcg1l00n4gFXnP8WXch7n; Mon, 17 Jun 2013 19:36:43 +0000 Received: from orthanc.internal (orthanc.internal [192.168.1.24]) by mail.gonehiking.org (Postfix) with ESMTP id 52D6280348; Mon, 17 Jun 2013 13:36:51 -0600 (MDT) From: Shuah Khan To: pavel@ucw.cz, rjw@sisk.pl, len.brown@intel.com, gregkh@linuxfoundation.org, joe@perches.com Cc: Shuah Khan , linux-pm@vger.kernel.org, linux-kernel@vger.kernel.org, shuahkhan@gmail.com Subject: [PATCHv v3] power: Include additional information in pm_print_times Date: Mon, 17 Jun 2013 13:36:35 -0600 Message-Id: <1371497795-20084-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=1371497803; bh=HkutgTaYWskCdJbXkmq/BcoavOVxXI/0GcCe4OYYHBA=; h=Received:Received:Received:From:To:Subject:Date:Message-Id; b=HEyiYdyvKYt8PDNwT9o6+z6DonjBx8jnSEUPDzurEaYxPixeqF0SP2S03yEV9RRKn 7CDqa41mDnirDKCIGTX1kz7PmEoV93rz9UglXNmnPRJ+SrC+Ya8748XHgXp13tysYV vdO3NeH4QeP9Ef007dd6TwAzV7REnS/GEkxz69saEerNTbT85kca/nH+97fI2uM8jn Ow8Ds6UtSCwRD5zdFtX5Op4sychASUO8IPP1GJbKvgbgSZMRgduwkSLTf7k6WYNWbf tWR1i1TeuF8SZa8KHUtGe1mKdh/TpnQlGmS3PPygblnPcvU+sgaY2l/gVULOTg8OVM HEf+3gbkknpPg== 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.9 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 Change __device_suspend() path to include driver name and the ops that get run for a device. This additional information helps associate the driver and the type of pm_ops the device uses in the suspend path very quickly, which will aid in debugging problems in suspend and resume paths. Changed both start and end debug messages to include pm_ops information and use dev_info() instead of pr_info(). Changed the end message to include parent device information and have the same format as the start message. dmesg output before the change: [ 164.390032] calling 1-1+ @ 69, parent: usb1 [ 164.390035] call 1-1+ returned 0 after 0 usecs [ 164.390352] calling 00:0a+ @ 2457, parent: pnp0 [ 164.390357] call 00:0a+ returned 0 after 3 usecs [ 164.390361] calling 00:09+ @ 2457, parent: pnp0 [ 164.496458] call 00:09+ returned 0 after 103500 usecs [ 164.496494] calling 00:05+ @ 2457, parent: pnp0 [ 164.496511] call 00:05+ returned 0 after 14 usecs dmesg output after the change: [ 545.985394] usb 1-1: Start: type pm ops @ 68, parent: usb1 [ 545.987650] usb 1-1: End : type pm ops @ 68, parent: usb1 time(2184 usecs) err(0) [ 545.982544] system 00:0a: Start: legacy bus pm ops @ 2391, parent: pnp0 [ 545.982554] system 00:0a: End : legacy bus pm ops @ 2391, parent: pnp0 time(4 usecs) err(0) [ 545.982569] tpm_tis 00:09: Start: legacy bus pm ops @ 2391, parent: pnp0 [ 546.087017] tpm_tis 00:09: End : legacy bus pm ops @ 2391, parent: pnp0 time(101936 usecs) err(0) [ 546.087069] rtc_cmos 00:05: Start: legacy bus pm ops @ 2391, parent: pnp0 [ 546.087084] rtc_cmos 00:05: End : legacy bus pm ops @ 2391, parent: pnp0 time(11 usecs) err(0) Signed-off-by: Shuah Khan Acked-by: Greg Kroah-Hartman --- v2: Change to use dev_info() instead of pr_info() v3: Change to add parent info to debug_report and make start and end messages look similar have a tighter association. drivers/base/power/main.c | 49 +++++++++++++++++++++++++++------------------ 1 file changed, 29 insertions(+), 20 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..c2132b8 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -157,13 +157,14 @@ void device_pm_move_last(struct device *dev) list_move_tail(&dev->power.entry, &dpm_list); } -static ktime_t initcall_debug_start(struct device *dev) +static ktime_t initcall_debug_start(struct device *dev, char *info) { ktime_t calltime = ktime_set(0, 0); if (pm_print_times_enabled) { - pr_info("calling %s+ @ %i, parent: %s\n", - dev_name(dev), task_pid_nr(current), + /* string in info has an extra space at the end */ + dev_info(dev, "Start: %s@ %i, parent: %s\n", + info, task_pid_nr(current), dev->parent ? dev_name(dev->parent) : "none"); calltime = ktime_get(); } @@ -172,15 +173,19 @@ static ktime_t initcall_debug_start(struct device *dev) } static void initcall_debug_report(struct device *dev, ktime_t calltime, - int error) + int error, char *info) { ktime_t delta, rettime; 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); + /* string in info has an extra space at the end */ + dev_info(dev, + "End : %s@ %i, parent: %s time(%llu usecs) err(%d)\n", + info, task_pid_nr(current), + dev->parent ? dev_name(dev->parent) : "none", + (unsigned long long)ktime_to_ns(delta) >> 10, error); } } @@ -373,13 +378,13 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev, if (!cb) return 0; - calltime = initcall_debug_start(dev); + calltime = initcall_debug_start(dev, info); pm_dev_dbg(dev, state, info); error = cb(dev); suspend_report_result(cb, error); - initcall_debug_report(dev, calltime, error); + initcall_debug_report(dev, calltime, error, info); return error; } @@ -1027,17 +1032,19 @@ 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; - calltime = initcall_debug_start(dev); + calltime = initcall_debug_start(dev, info); + pm_dev_dbg(dev, state, info); error = cb(dev, state); suspend_report_result(cb, error); - initcall_debug_report(dev, calltime, error); + initcall_debug_report(dev, calltime, error, info); return error; } @@ -1079,43 +1086,45 @@ static int __device_suspend(struct device *dev, pm_message_t state, bool async) device_lock(dev); if (dev->pm_domain) { - info = "power domain "; + info = "power domain pm ops "; callback = pm_op(&dev->pm_domain->ops, state); goto Run; } if (dev->type && dev->type->pm) { - info = "type "; + info = "type pm ops "; callback = pm_op(dev->type->pm, state); goto Run; } if (dev->class) { if (dev->class->pm) { - info = "class "; + info = "class pm ops "; callback = pm_op(dev->class->pm, state); goto Run; } else if (dev->class->suspend) { - pm_dev_dbg(dev, state, "legacy class "); - error = legacy_suspend(dev, state, dev->class->suspend); + info = "legacy class pm ops "; + error = legacy_suspend(dev, state, dev->class->suspend, + info); goto End; } } if (dev->bus) { if (dev->bus->pm) { - info = "bus "; + info = "bus pm ops "; 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); + info = "legacy bus pm ops "; + error = legacy_suspend(dev, state, dev->bus->suspend, + info); goto End; } } Run: if (!callback && dev->driver && dev->driver->pm) { - info = "driver "; + info = "driver pm ops "; callback = pm_op(dev->driver->pm, state); }