From patchwork Fri Jun 14 20:35:24 2013 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Shuah Khan X-Patchwork-Id: 2724251 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 63D6EC0AB1 for ; Fri, 14 Jun 2013 20:35:34 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 5885020286 for ; Fri, 14 Jun 2013 20:35:33 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 3B6A920279 for ; Fri, 14 Jun 2013 20:35:32 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753831Ab3FNUfb (ORCPT ); Fri, 14 Jun 2013 16:35:31 -0400 Received: from qmta15.emeryville.ca.mail.comcast.net ([76.96.27.228]:58845 "EHLO qmta15.emeryville.ca.mail.comcast.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753829Ab3FNUfa (ORCPT ); Fri, 14 Jun 2013 16:35:30 -0400 Received: from omta22.emeryville.ca.mail.comcast.net ([76.96.30.89]) by qmta15.emeryville.ca.mail.comcast.net with comcast id oLQp1l0061vN32cAFLbWii; Fri, 14 Jun 2013 20:35:30 +0000 Received: from mail.gonehiking.org ([75.71.126.216]) by omta22.emeryville.ca.mail.comcast.net with comcast id oLbT1l0184gFXnP8iLbUwV; Fri, 14 Jun 2013 20:35:30 +0000 Received: from orthanc.internal (orthanc.internal [192.168.1.24]) by mail.gonehiking.org (Postfix) with ESMTP id DED208001F; Fri, 14 Jun 2013 14:35:33 -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: [PATCH v2] power: Include additional information in pm_print_times Date: Fri, 14 Jun 2013 14:35:24 -0600 Message-Id: <1371242124-11452-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=1371242130; bh=Ushc6nsZx6hRmOs37Ao+byauRxlwtpnO8j1E3CnRX58=; h=Received:Received:Received:From:To:Subject:Date:Message-Id; b=IkDUVNXaoLp4nd3PsdSrQPLiObRrqnzt7aHEoF5WdKkprpebEa2WzYm1sFzdrqQUM aOfi0wIMbURxTnpTbkdCcD9QwhPbwnyn+wGQa1SmAo+0CbqXp4Q01TvVMPLO/xko7t IWRDL4WeeD45nD0W1Ngevpx951Vx6onrhbt1Vd1QdKksToowHapqciXTIzq/K954RL N54LEY9XTvK6DBbFcy7851tFRSf4cJU/xsneybM2rwJ+YH9LRFsVFFuXil9AKW7k87 DBVX3I1o3xPCHer8WW0i1KwXy9N63oMGCaBfHDZI6HIVRnG2TLrZJsBd7J+aV00LV8 kiYP5oeYegUpw== 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.1 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 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(). 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: [ 58.707002] usb usb1: calling type pm ops @ 57, parent: 0000:00:1d.0 [ 58.707641] usb usb1: call type pm ops returned 0 after 611 usecs [ 58.702014] system 00:0a: calling legacy bus pm ops @ 2173, parent: pnp0 [ 58.702018] system 00:0a: call legacy bus pm ops returned 0 after 2 usecs [ 58.702023] tpm_tis 00:09: calling legacy bus pm ops @ 2173, parent: pnp0 [ 58.806909] tpm_tis 00:09: call legacy bus pm ops returned 0 after 102425 usecs [ 58.806927] rtc_cmos 00:05: calling legacy bus pm ops @ 2173, parent: pnp0 [ 58.806935] rtc_cmos 00:05: call legacy bus pm ops returned 0 after 5 usecs Signed-off-by: Shuah Khan Acked-by: Greg Kroah-Hartman --- drivers/base/power/main.c | 44 +++++++++++++++++++++++++------------------- 1 file changed, 25 insertions(+), 19 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 5a9b656..e8d2de7 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, "calling %s@ %i, parent: %s\n", + info, task_pid_nr(current), dev->parent ? dev_name(dev->parent) : "none"); calltime = ktime_get(); } @@ -172,14 +173,15 @@ 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), + /* string in info has an extra space at the end */ + dev_info(dev, "call %sreturned %d after %llu usecs\n", info, error, (unsigned long long)ktime_to_ns(delta) >> 10); } } @@ -373,13 +375,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 +1029,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 +1083,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); }