2022-11-21 05:12:13

by Thomas Weißschuh

Subject: [PATCH] power: process: use explicit levels for printk continuations

Many of the printk messages emitted during suspend and resume are
emitted in fragments using pr_cont()/KERN_CONT.

As during suspend and resume a lot of operations are happing in the
kernel the chances are high that the fragments are interspersed with
unrelated messages.

In this case if no explicit level is specified for the fragments the
standard level is applied, which by default is KERN_WARNING.

If the user is only observing KERN_WARNING and *not* KERN_INFO messages
they will see incomplete message fragments.

By specifing the correct printk level also with the continuations this
mismatch can be avoided.
Also it reduces the amount of false-positive KERN_WARNING messages.

Signed-off-by: Thomas Weißschuh <[email protected]>
---
kernel/power/process.c | 16 ++++++++--------
1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/kernel/power/process.c b/kernel/power/process.c
index ddd9988327fe..0a828edc6d30 100644
--- a/kernel/power/process.c
+++ b/kernel/power/process.c
@@ -82,7 +82,7 @@ static int try_to_freeze_tasks(bool user_only)
elapsed_msecs = ktime_to_ms(elapsed);

if (todo) {
- pr_cont("\n");
+ pr_info(KERN_CONT "\n");
pr_err("Freezing of tasks %s after %d.%03d seconds "
"(%d tasks refusing to freeze, wq_busy=%d):\n",
wakeup ? "aborted" : "failed",
@@ -101,7 +101,7 @@ static int try_to_freeze_tasks(bool user_only)
read_unlock(&tasklist_lock);
}
} else {
- pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
+ pr_info(KERN_CONT "(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
elapsed_msecs % 1000);
}

@@ -135,9 +135,9 @@ int freeze_processes(void)
error = try_to_freeze_tasks(true);
if (!error) {
__usermodehelper_set_disable_depth(UMH_DISABLED);
- pr_cont("done.");
+ pr_info(KERN_CONT "done.");
}
- pr_cont("\n");
+ pr_info(KERN_CONT "\n");
BUG_ON(in_atomic());

/*
@@ -171,9 +171,9 @@ int freeze_kernel_threads(void)
pm_nosig_freezing = true;
error = try_to_freeze_tasks(false);
if (!error)
- pr_cont("done.");
+ pr_info(KERN_CONT "done.");

- pr_cont("\n");
+ pr_info(KERN_CONT "\n");
BUG_ON(in_atomic());

if (error)
@@ -215,7 +215,7 @@ void thaw_processes(void)
usermodehelper_enable();

schedule();
- pr_cont("done.\n");
+ pr_info(KERN_CONT "done.\n");
trace_suspend_resume(TPS("thaw_processes"), 0, false);
}

@@ -236,5 +236,5 @@ void thaw_kernel_threads(void)
read_unlock(&tasklist_lock);

schedule();
- pr_cont("done.\n");
+ pr_info(KERN_CONT "done.\n");
}

base-commit: eb7081409f94a9a8608593d0fb63a1aa3d6f95d8
--
2.38.1

2022-11-21 16:21:08

by Petr Mladek

Subject: Re: [PATCH] power: process: use explicit levels for printk continuations

On Mon 2022-11-21 06:09:46, Thomas Wei?schuh wrote:
> Many of the printk messages emitted during suspend and resume are
> emitted in fragments using pr_cont()/KERN_CONT.
>
> As during suspend and resume a lot of operations are happing in the
> kernel the chances are high that the fragments are interspersed with
> unrelated messages.
>
> In this case if no explicit level is specified for the fragments the
> standard level is applied, which by default is KERN_WARNING.
>
> If the user is only observing KERN_WARNING and *not* KERN_INFO messages
> they will see incomplete message fragments.
>
> By specifing the correct printk level also with the continuations this
> mismatch can be avoided.
> Also it reduces the amount of false-positive KERN_WARNING messages.

Yup, it is a known printk() limitation and this is the most reliable
solution.

> Signed-off-by: Thomas Wei?schuh <[email protected]>
> ---
> kernel/power/process.c | 16 ++++++++--------
> 1 file changed, 8 insertions(+), 8 deletions(-)
>
> diff --git a/kernel/power/process.c b/kernel/power/process.c
> index ddd9988327fe..0a828edc6d30 100644
> --- a/kernel/power/process.c
> +++ b/kernel/power/process.c
> @@ -101,7 +101,7 @@ static int try_to_freeze_tasks(bool user_only)
> read_unlock(&tasklist_lock);
> }
> } else {
> - pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
> + pr_info(KERN_CONT "(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,

It looks a bit ugly. Feel free to provide separate patch introducing
pr_<level>_cont() wrappers. Then you could use pr_info_cont() here.

We already have pr_<level>_once() and pr_<level>_ratelimited().
So pr_<level>_cont() would fit the existing pattern.


> elapsed_msecs % 1000);
> }
>

Best Regards,
Petr