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@xxxxxxxxxxxxxxx>
> ---
>
> 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@xxxxxxxxx>

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