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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [day] [month] [year] [list]

Message-ID: <2wuf3xlvzvnkddddblsnomulhjpst2vezimulwgtjlczl3pnvu@qf7ypuuuvylz>
Date: Mon, 7 Apr 2025 09:17:15 -0500
From: Lucas De Marchi <lucas.demarchi@...el.com>
To: Andrew Sayers <kernel.org@...eofstuff.org>
CC: "Rafael J. Wysocki" <rafael@...nel.org>, Pavel Machek <pavel@...nel.org>,
	Len Brown <len.brown@...el.com>, Todd E Brandt
	<todd.e.brandt@...ux.intel.com>, <linux-pm@...r.kernel.org>,
	<linux-kernel@...r.kernel.org>
Subject: Re: [PATCH] PM: Use two lines for "Restarting..." / "done" messages

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@...eofstuff.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@...el.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
>