From patchwork Thu Oct 20 00:26:09 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Brian Norris X-Patchwork-Id: 9385621 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id DE59860487 for ; Thu, 20 Oct 2016 00:26:52 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id D3B0B29002 for ; Thu, 20 Oct 2016 00:26:52 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id C6B5929087; Thu, 20 Oct 2016 00:26:52 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.8 required=2.0 tests=BAYES_00,DKIM_SIGNED, RCVD_IN_DNSWL_HI,T_DKIM_INVALID autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id CA24229002 for ; Thu, 20 Oct 2016 00:26:51 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753869AbcJTA0u (ORCPT ); Wed, 19 Oct 2016 20:26:50 -0400 Received: from mail-pf0-f173.google.com ([209.85.192.173]:36298 "EHLO mail-pf0-f173.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753560AbcJTA0s (ORCPT ); Wed, 19 Oct 2016 20:26:48 -0400 Received: by mail-pf0-f173.google.com with SMTP id e6so24606125pfk.3 for ; Wed, 19 Oct 2016 17:26:48 -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=F1SqxkVLRoo0chirWmsjZ9FdhrKxei8oDgpmRJuTFgg=; b=eRmbmoJFvV5P+Fil6fig4OGNzSwYQkNF+KyidzzjqeGATgNi6SFWnbo4AKJMNHpP0V tqrnhWjJPnQE0BN3N0Y99ITmlR2EgC3U84ZlafVqn2DPwBs6mrjcjDSSQCZk/svqiqL0 yYl9TmGdS6Y71SittbgwM79G6ZmtvWv4sCuTk= 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=F1SqxkVLRoo0chirWmsjZ9FdhrKxei8oDgpmRJuTFgg=; b=dyvorCQ56Y7XwASrc/Wtl/IRVCsSpYvadN3K60EtVRe+MxohR0URgrHe1iXlhkzAi6 CJQJG8cYxGjy7CXVe3WWiBdD3JlVXn6irPtHSHFa0p07ZzlbW4C/LiD49lbcTR1/escy hjlMwuXzjzbwYMpdmoXLU759iBeunu7GOmS3wvrDgTFzf8qNRMk8qIsgpmQEXZ6y62Gq lCk8hgBq93awFlfH7S2RqobX4OIkve8Wp6F8qR40jpdPQrmr1WGP4fwlo7hOna0yeTKl kW4PJeVtrSKgirtIH42xGqbQFVB9kjjH9Ri3l1iGypHqYHpKQsSDd1xgTMVchRz7VHHh z3Dg== X-Gm-Message-State: AA6/9Rmy+6mF8ept+EZa10ImprILT08JhJ3YnD0UO9gC5djsoCBtbBpO4zcThWuKcGcpBqA9 X-Received: by 10.99.53.6 with SMTP id c6mr13216210pga.179.1476923207982; Wed, 19 Oct 2016 17:26:47 -0700 (PDT) Received: from ban.mtv.corp.google.com ([172.22.64.120]) by smtp.gmail.com with ESMTPSA id b139sm44359287pfb.8.2016.10.19.17.26.46 (version=TLS1_2 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 19 Oct 2016 17:26:47 -0700 (PDT) From: Brian Norris To: "Rafael J . Wysocki" , Pavel Machek , Len Brown , Greg Kroah-Hartman Cc: , Doug Anderson , Brian Norris , Jeffy Chen , linux-pm@vger.kernel.org, Chuansheng Liu , Dmitry Torokhov , Brian Norris Subject: [RESEND PATCH 1/2] PM / sleep: print function name of callbacks Date: Wed, 19 Oct 2016 17:26:09 -0700 Message-Id: <1476923170-111986-1-git-send-email-briannorris@chromium.org> X-Mailer: git-send-email 2.8.0.rc3.226.g39d4020 Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP From: Douglas Anderson 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 Signed-off-by: Brian Norris Reviewed-by: Dmitry Torokhov --- This is a resend of the following patch (w/ minor $subject alteration): https://patchwork.kernel.org/patch/7241641/ It was useful for debugging the following patch, so I thought I'd resend. It received an Ack the first time. 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 e44944f4be77..c58563581345 100644 --- a/drivers/base/power/main.c +++ b/drivers/base/power/main.c @@ -190,14 +190,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(); } @@ -384,7 +384,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); @@ -1330,7 +1330,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);