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

[Rafael J. Wysocki]

On Fri, Apr 11, 2025 at 5:27 PM Andrew Sayers
<kernel.org@xxxxxxxxxxxxxxx> 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.
>
> Change the messages to "<event>..." / "Done <event>.", unlike a449dfbfc089
> which uses "<event>..." / "<event> completed.".  Front-loading the unique
> part of the message makes it easier to scan the log, and reduces ambiguity
> for users who aren't confident in their English comprehension.
>
> Reviewed-by: Lucas De Marchi <lucas.demarchi@xxxxxxxxx>
> Signed-off-by: Andrew Sayers <kernel.org@xxxxxxxxxxxxxxx>
> ---
> v1 -> v2: mentioned a449dfbfc089 in commit message (thanks Lucas De Marchi)
>
>  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 e2261f33a082..1555b51a7d55 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)
> --

Applied as 6.16 material, thanks!