From patchwork Tue Sep 22 17:26:37 2015 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Doug Anderson X-Patchwork-Id: 7241651 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.29.136]) by patchwork1.web.kernel.org (Postfix) with ESMTP id 1A7AC9F443 for ; Tue, 22 Sep 2015 17:27:37 +0000 (UTC) Received: from mail.kernel.org (localhost [127.0.0.1]) by mail.kernel.org (Postfix) with ESMTP id 400B4209C3 for ; Tue, 22 Sep 2015 17:27:36 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.kernel.org (Postfix) with ESMTP id 5D465209D3 for ; Tue, 22 Sep 2015 17:27:35 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758548AbbIVR1V (ORCPT ); Tue, 22 Sep 2015 13:27:21 -0400 Received: from mail-pa0-f54.google.com ([209.85.220.54]:36718 "EHLO mail-pa0-f54.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1758037AbbIVR1G (ORCPT ); Tue, 22 Sep 2015 13:27:06 -0400 Received: by pacgz1 with SMTP id gz1so12064711pac.3 for ; Tue, 22 Sep 2015 10:27:05 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=chromium.org; s=google; h=from:to:cc:subject:date:message-id; bh=kI6MXdBCojnO4EI0jzX39Oyl7zJ1dugdrfwEbrjT/Fc=; b=CoS3ghmxwKQR0wZjivqHEx70xNCsPn4ahgYpe5sfpvnw7pm2yMZ5mQ8bIB6NlqswP+ 3HWrcmbHymfu76mo3IMxke8ScKRXuOp0zyoZ0sHky1s6v7n+L0qfWgwbo7OpoKybWF9S akb1LwG/du+TH17uTFyCJctNcCAw1IGND9n1E= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id; bh=kI6MXdBCojnO4EI0jzX39Oyl7zJ1dugdrfwEbrjT/Fc=; b=kQGBaIZwBlMDpRIqYDi5C3VbhIKTZXdBhGwCmhVVIPLJIwOGyJqu1o8y2oL4KpY8bo w+mX8aA55ZN+FsPunq8RmdsSVH5+VKyU2Jhn5EV2tAmWfA0qjA8GYWgUSv05N6rwM8jr CQX08InKH+Dp6ggSpnP7mNAIEMzDPWQDJclIl6in5HX3uHEV8kunvGMFHELia8VcLiXJ tCIqdqyfKditK1ZSrFjbxdDIXucS2CjQ2RrGBziVKXKwbn/Y6gY1KhRR0pJ5CLkJSwtW w4oJXFTxbODBX0yyQkBqJfT3EHO1S/s+DajeR9Wqc4RAisJnDS3nYu1WrPnUtJmXDItH d+8g== X-Gm-Message-State: ALoCoQkjsvZL41VlCq6jCAzW1mFCGkfY+aXQFt8xByMToZhY7QQ5ExOoOoJwM4k3mNUu68AJ3RJx X-Received: by 10.69.20.1 with SMTP id gy1mr940792pbd.125.1442942825179; Tue, 22 Sep 2015 10:27:05 -0700 (PDT) Received: from tictac.mtv.corp.google.com ([172.22.65.76]) by smtp.gmail.com with ESMTPSA id gi4sm3443490pbc.4.2015.09.22.10.27.04 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 22 Sep 2015 10:27:04 -0700 (PDT) From: Douglas Anderson To: rjw@rjwysocki.net Cc: Dmitry Torokhov , Douglas Anderson , pavel@ucw.cz, len.brown@intel.com, gregkh@linuxfoundation.org, linux-pm@vger.kernel.org, linux-kernel@vger.kernel.org Subject: [PATCH] power: print function name of callbacks Date: Tue, 22 Sep 2015 10:26:37 -0700 Message-Id: <1442942797-17433-1-git-send-email-dianders@chromium.org> X-Mailer: git-send-email 2.6.0.rc0.131.gf624c3d Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Spam-Status: No, score=-6.8 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 The printouts writen to the logs by suspend can be a bit opaque: it can be hard to track them down to the actual function called. You might see: calling rfkill1+ @ 19473, parent: phy0 call rfkill1+ returned 0 after 1 usecs calling phy0+ @ 19473, parent: mmc2:0001:1 call phy0+ returned 0 after 19 usecs It's a bit hard to know what's actually happening. Instead, it's nice to see: calling rfkill1+ @ 15793, parent: phy0, cb: rfkill_suspend call rfkill1+ returned 0 after 1 usecs calling phy0+ @ 15793, parent: mmc2:0001:1, cb: wiphy_suspend [cfg80211] call phy0+ returned 0 after 7 usecs That makes it very obvious what's going on. It also has the nice side effect of making the suspend/resume spew a little more obvious, since many resume functions have the word "resume" in the name: calling phy0+ @ 15793, parent: mmc2:0001:1, cb: wiphy_resume [cfg80211] call phy0+ returned 0 after 12 usecs calling rfkill1+ @ 15793, parent: phy0, cb: rfkill_resume call rfkill1+ returned 0 after 1 usecs Signed-off-by: Douglas Anderson Acked-by: Pavel Machek --- drivers/base/power/main.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c index 1710c26..e2b1f14 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -188,14 +188,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, void *cb) { ktime_t calltime = ktime_set(0, 0); if (pm_print_times_enabled) { - pr_info("calling %s+ @ %i, parent: %s\n", + pr_info("calling %s+ @ %i, parent: %s, cb: %pf\n", dev_name(dev), task_pid_nr(current), - dev->parent ? dev_name(dev->parent) : "none"); + dev->parent ? dev_name(dev->parent) : "none", cb); calltime = ktime_get(); } @@ -382,7 +382,7 @@ 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, cb); pm_dev_dbg(dev, state, info); trace_device_pm_callback_start(dev, info, state.event); @@ -1324,7 +1324,7 @@ static int legacy_suspend(struct device *dev, pm_message_t state, int error; ktime_t calltime; - calltime = initcall_debug_start(dev); + calltime = initcall_debug_start(dev, cb); trace_device_pm_callback_start(dev, info, state.event); error = cb(dev, state);