[PATCH] PM: Use two lines for "Restarting..." / "done" messages

[PATCH] PM: Use two lines for "Restarting..." / "done" messages

[Andrew Sayers]

Other messages are occasionally printed between these two, for example:

    [203104.106534] Restarting tasks ...
    [203104.106559] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops [i915])
    [203104.112354] done.

This seems to be a timing issue, seen in two of the eleven
hibernation exits in my current `dmesg` output.

When printed on its own, the "done" message has the default log level.
This makes the output of `dmesg --level=warn` quite misleading.

Add enough context for the "done" messages to make sense on their own,
and use the same log level for all messages.

Signed-off-by: Andrew Sayers <kernel.org@pileofstuff.org>
---

I haven't been able to trigger "Restarting kernel threads" at all,
so can only prove the above occurs for "Restarting tasks".
But inspecting the code suggests it's possible, and it
seems more elegant for both pairs to look the same.

 kernel/power/process.c             | 8 ++++----
 tools/power/pm-graph/sleepgraph.py | 3 ++-
 2 files changed, 6 insertions(+), 5 deletions(-)

diff --git a/kernel/power/process.c b/kernel/power/process.c
index 66ac067d9ae6..4c674282df03 100644
--- a/kernel/power/process.c
+++ b/kernel/power/process.c
@@ -189,7 +189,7 @@ void thaw_processes(void)
 
 	oom_killer_enable();
 
-	pr_info("Restarting tasks ... ");
+	pr_info("Restarting tasks ...\n");
 
 	__usermodehelper_set_disable_depth(UMH_FREEZING);
 	thaw_workqueues();
@@ -208,7 +208,7 @@ void thaw_processes(void)
 	usermodehelper_enable();
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info("Done restarting tasks.\n");
 	trace_suspend_resume(TPS("thaw_processes"), 0, false);
 }
 
@@ -217,7 +217,7 @@ void thaw_kernel_threads(void)
 	struct task_struct *g, *p;
 
 	pm_nosig_freezing = false;
-	pr_info("Restarting kernel threads ... ");
+	pr_info("Restarting kernel threads ...\n");
 
 	thaw_workqueues();
 
@@ -229,5 +229,5 @@ void thaw_kernel_threads(void)
 	read_unlock(&tasklist_lock);
 
 	schedule();
-	pr_cont("done.\n");
+	pr_info("Done restarting kernel threads.\n");
 }
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
index 918eae58b0b4..b608c7b44b5d 100755
--- a/tools/power/pm-graph/sleepgraph.py
+++ b/tools/power/pm-graph/sleepgraph.py
@@ -4017,7 +4017,8 @@ def parseKernelLog(data):
 							'PM: early restore of devices complete after.*'],
 		'resume_complete': ['PM: resume of devices complete after.*',
 							'PM: restore of devices complete after.*'],
-		    'post_resume': [r'.*Restarting tasks \.\.\..*'],
+		    'post_resume': [r'.*Restarting tasks \.\.\..*',
+							'Done restarting tasks.*'],
 	}
 
 	# action table (expected events that occur and show up in dmesg)
-- 
2.47.2

Re: [PATCH] PM: Use two lines for "Restarting..." / "done" messages

[Lucas De Marchi]

On Tue, Mar 11, 2025 at 01:00:37PM +0000, Andrew Sayers wrote:
>Other messages are occasionally printed between these two, for example:
>
>    [203104.106534] Restarting tasks ...
>    [203104.106559] mei_hdcp 0000:00:16.0-b638ab7e-94e2-4ea2-a552-d1c54b627f04: bound 0000:00:02.0 (ops i915_hdcp_ops [i915])
>    [203104.112354] done.
>
>This seems to be a timing issue, seen in two of the eleven
>hibernation exits in my current `dmesg` output.
>
>When printed on its own, the "done" message has the default log level.
>This makes the output of `dmesg --level=warn` quite misleading.
>
>Add enough context for the "done" messages to make sense on their own,
>and use the same log level for all messages.
>
>Signed-off-by: Andrew Sayers <kernel.org@pileofstuff.org>
>---
>
>I haven't been able to trigger "Restarting kernel threads" at all,
>so can only prove the above occurs for "Restarting tasks".
>But inspecting the code suggests it's possible, and it
>seems more elegant for both pairs to look the same.
>
> kernel/power/process.c             | 8 ++++----
> tools/power/pm-graph/sleepgraph.py | 3 ++-
> 2 files changed, 6 insertions(+), 5 deletions(-)
>
>diff --git a/kernel/power/process.c b/kernel/power/process.c
>index 66ac067d9ae6..4c674282df03 100644
>--- a/kernel/power/process.c
>+++ b/kernel/power/process.c
>@@ -189,7 +189,7 @@ void thaw_processes(void)
>
> 	oom_killer_enable();
>
>-	pr_info("Restarting tasks ... ");
>+	pr_info("Restarting tasks ...\n");
>
> 	__usermodehelper_set_disable_depth(UMH_FREEZING);
> 	thaw_workqueues();
>@@ -208,7 +208,7 @@ void thaw_processes(void)
> 	usermodehelper_enable();
>
> 	schedule();
>-	pr_cont("done.\n");
>+	pr_info("Done restarting tasks.\n");


This indeed shows up a occasional issue in our graphics CI farm. I
thought I had a patch handling that and while trying to find it I ended
finding this one. So I probably I never sent the patch :-/. This one would
work nicely for us.

Maybe also mention commit a449dfbfc089 ("PM: sleep: Avoid using
pr_cont() in the tasks freezing code") in the sommit message that did
something similar for freezing the tasks?

After applying this patch, the only user of pr_cont/KERN_CONT I see with
"done" are places that would not affect normal CI tests:

	$ git grep "pr.*(.*\"[Dd]one\."  | grep -i cont
	arch/openrisc/kernel/sync-timer.c:      pr_cont("done.\n");
	init/do_mounts_rd.c:    pr_cont("done.\n");

Reviewed-by: Lucas De Marchi <lucas.demarchi@intel.com>

thanks
Lucas De Marchi

> 	trace_suspend_resume(TPS("thaw_processes"), 0, false);
> }
>
>@@ -217,7 +217,7 @@ void thaw_kernel_threads(void)
> 	struct task_struct *g, *p;
>
> 	pm_nosig_freezing = false;
>-	pr_info("Restarting kernel threads ... ");
>+	pr_info("Restarting kernel threads ...\n");
>
> 	thaw_workqueues();
>
>@@ -229,5 +229,5 @@ void thaw_kernel_threads(void)
> 	read_unlock(&tasklist_lock);
>
> 	schedule();
>-	pr_cont("done.\n");
>+	pr_info("Done restarting kernel threads.\n");
> }
>diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
>index 918eae58b0b4..b608c7b44b5d 100755
>--- a/tools/power/pm-graph/sleepgraph.py
>+++ b/tools/power/pm-graph/sleepgraph.py
>@@ -4017,7 +4017,8 @@ def parseKernelLog(data):
> 							'PM: early restore of devices complete after.*'],
> 		'resume_complete': ['PM: resume of devices complete after.*',
> 							'PM: restore of devices complete after.*'],
>-		    'post_resume': [r'.*Restarting tasks \.\.\..*'],
>+		    'post_resume': [r'.*Restarting tasks \.\.\..*',
>+							'Done restarting tasks.*'],
> 	}
>
> 	# action table (expected events that occur and show up in dmesg)
>-- 
>2.47.2
>