[PATCH 0/3] PM / core: Clean up suspend/resume diagnostic messages

[PATCH 0/3] PM / core: Clean up suspend/resume diagnostic messages

[Bjorn Helgaas]

These are pretty minor cleanups to the suspend/resume diagnostic messages.

The first two are trivial.  The third may break scripts that parse dmesg
output.  I looked at scripts/bootgraph.pl, and I don't think it is
affected, but there may be others I don't know about.  Let me know if there
are.

---

Bjorn Helgaas (3):
      PM / core: Remove unused initcall_debug_report() arguments
      PM / core: Simplify initcall_debug_report() timing
      PM / core: Use dev_printk() and symbols in suspend/resume diagnostics


 drivers/base/power/main.c |   37 +++++++++++++++++--------------------
 1 file changed, 17 insertions(+), 20 deletions(-)

[PATCH 1/3] PM / core: Remove unused initcall_debug_report() arguments

[Bjorn Helgaas]

From: Bjorn Helgaas <bhelgaas@google.com>

e8bca479c3f2 ("PM / sleep: trace events for device PM callbacks") removed
the only uses of "state" and "info" from initcall_debug_report().

Remove the now-unused arguments completely.

Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
 drivers/base/power/main.c |    7 +++----
 1 file changed, 3 insertions(+), 4 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 02a497e7c785..85ef2af6dc92 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -207,8 +207,7 @@ static ktime_t initcall_debug_start(struct device *dev)
 }
 
 static void initcall_debug_report(struct device *dev, ktime_t calltime,
-				  int error, pm_message_t state,
-				  const char *info)
+				  int error)
 {
 	ktime_t rettime;
 	s64 nsecs;
@@ -454,7 +453,7 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
 	trace_device_pm_callback_end(dev, error);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error, state, info);
+	initcall_debug_report(dev, calltime, error);
 
 	return error;
 }
@@ -1671,7 +1670,7 @@ static int legacy_suspend(struct device *dev, pm_message_t state,
 	trace_device_pm_callback_end(dev, error);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error, state, info);
+	initcall_debug_report(dev, calltime, error);
 
 	return error;
 }

[PATCH 2/3] PM / core: Simplify initcall_debug_report() timing

[Bjorn Helgaas]

From: Bjorn Helgaas <bhelgaas@google.com>

initcall_debug_report() always called ktime_get(), even if we didn't need
the result.

Change it so we only call it when we're going to use the result, and change
initcall_debug_start() to follow the same style.

Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
 drivers/base/power/main.c |   24 +++++++++++-------------
 1 file changed, 11 insertions(+), 13 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index 85ef2af6dc92..b32750d18b09 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -194,16 +194,13 @@ void device_pm_move_last(struct device *dev)
 
 static ktime_t initcall_debug_start(struct device *dev)
 {
-	ktime_t calltime = 0;
-
-	if (pm_print_times_enabled) {
-		pr_info("calling  %s+ @ %i, parent: %s\n",
-			dev_name(dev), task_pid_nr(current),
-			dev->parent ? dev_name(dev->parent) : "none");
-		calltime = ktime_get();
-	}
+	if (!pm_print_times_enabled)
+		return 0;
 
-	return calltime;
+	pr_info("calling  %s+ @ %i, parent: %s\n",
+		dev_name(dev), task_pid_nr(current),
+		dev->parent ? dev_name(dev->parent) : "none");
+	return ktime_get();
 }
 
 static void initcall_debug_report(struct device *dev, ktime_t calltime,
@@ -212,13 +209,14 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
 	ktime_t rettime;
 	s64 nsecs;
 
+	if (!pm_print_times_enabled)
+		return;
+
 	rettime = ktime_get();
 	nsecs = (s64) ktime_to_ns(ktime_sub(rettime, calltime));
 
-	if (pm_print_times_enabled) {
-		pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
-			error, (unsigned long long)nsecs >> 10);
-	}
+	pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
+		error, (unsigned long long)nsecs >> 10);
 }
 
 /**

[PATCH 3/3] PM / core: Use dev_printk() and symbols in suspend/resume diagnostics

[Bjorn Helgaas]

From: Bjorn Helgaas <bhelgaas@google.com>

When we print diagnostic messages about suspend/resume, we have a device
pointer, so use dev_printk() to match other device-related things.  Add the
function name, similar to initcall_debug output.  E.g.,

  - calling  0000:01:00.0+ @ 998, parent: 0000:00:1c.0
  + pci 0000:01:00.0: calling <something> @ 998, parent: 0000:00:1c.0

I wondered if this would break scripts/bootgraph.pl, but I don't think it
will because bootgraph.pl doesn't add any timing information to $start{}
after it sees "Write protecting the" or "Freeing unused kernel memory".

But please let me know if it does break something that parses dmesg output.

Signed-off-by: Bjorn Helgaas <bhelgaas@google.com>
---
 drivers/base/power/main.c |   22 +++++++++++-----------
 1 file changed, 11 insertions(+), 11 deletions(-)

diff --git a/drivers/base/power/main.c b/drivers/base/power/main.c
index b32750d18b09..dceda0495abf 100644
--- a/drivers/base/power/main.c
+++ b/drivers/base/power/main.c
@@ -192,19 +192,19 @@ 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)
 {
 	if (!pm_print_times_enabled)
 		return 0;
 
-	pr_info("calling  %s+ @ %i, parent: %s\n",
-		dev_name(dev), task_pid_nr(current),
-		dev->parent ? dev_name(dev->parent) : "none");
+	dev_info(dev, "calling %pF @ %i, parent: %s\n", cb,
+		 task_pid_nr(current),
+		 dev->parent ? dev_name(dev->parent) : "none");
 	return ktime_get();
 }
 
 static void initcall_debug_report(struct device *dev, ktime_t calltime,
-				  int error)
+				  void *cb, int error)
 {
 	ktime_t rettime;
 	s64 nsecs;
@@ -215,8 +215,8 @@ static void initcall_debug_report(struct device *dev, ktime_t calltime,
 	rettime = ktime_get();
 	nsecs = (s64) ktime_to_ns(ktime_sub(rettime, calltime));
 
-	pr_info("call %s+ returned %d after %Ld usecs\n", dev_name(dev),
-		error, (unsigned long long)nsecs >> 10);
+	dev_info(dev, "%pF returned %d after %Ld usecs\n", cb, error,
+		 (unsigned long long)nsecs >> 10);
 }
 
 /**
@@ -443,7 +443,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);
@@ -451,7 +451,7 @@ static int dpm_run_callback(pm_callback_t cb, struct device *dev,
 	trace_device_pm_callback_end(dev, error);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, cb, error);
 
 	return error;
 }
@@ -1661,14 +1661,14 @@ 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);
 	trace_device_pm_callback_end(dev, error);
 	suspend_report_result(cb, error);
 
-	initcall_debug_report(dev, calltime, error);
+	initcall_debug_report(dev, calltime, cb, error);
 
 	return error;
 }

Re: [PATCH 0/3] PM / core: Clean up suspend/resume diagnostic messages

[Pavel Machek]

[-- Attachment #1: Type: text/plain, Size: 562 bytes --]

On Thu 2018-04-26 16:36:20, Bjorn Helgaas wrote:
> These are pretty minor cleanups to the suspend/resume diagnostic messages.
> 
> The first two are trivial.  The third may break scripts that parse dmesg
> output.  I looked at scripts/bootgraph.pl, and I don't think it is
> affected, but there may be others I don't know about.  Let me know if there
> are.

Looks good.

Acked-by: Pavel Machek <pavel@ucw.cz>

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: Digital signature --]
[-- Type: application/pgp-signature, Size: 181 bytes --]

Re: [PATCH 0/3] PM / core: Clean up suspend/resume diagnostic messages

[Rafael J. Wysocki]

On Thursday, April 26, 2018 11:36:20 PM CEST Bjorn Helgaas wrote:
> These are pretty minor cleanups to the suspend/resume diagnostic messages.
> 
> The first two are trivial.  The third may break scripts that parse dmesg
> output.  I looked at scripts/bootgraph.pl, and I don't think it is
> affected, but there may be others I don't know about.  Let me know if there
> are.
> 
> ---
> 
> Bjorn Helgaas (3):
>       PM / core: Remove unused initcall_debug_report() arguments
>       PM / core: Simplify initcall_debug_report() timing
>       PM / core: Use dev_printk() and symbols in suspend/resume diagnostics
> 
> 
>  drivers/base/power/main.c |   37 +++++++++++++++++--------------------
>  1 file changed, 17 insertions(+), 20 deletions(-)
> 

All [1-3/3] applied, thanks!