[v2,0/3] printk: introduce new macros pr_<level>_cont()

  This series adds new printk wrapper macros pr_<level>_cont().
These create continuation messages with an explicit level.

Explicit levels are useful when a continuation message is split from its main
message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
which can lead to stray partial log messages when filtering by level.

Also checkpatch is modified to recommend the new macros over plain pr_cont().

Lastly the new macros are used in kernel/power/process.c as this file uses
continuation messages during system suspend-resume which creates a high
likelyhood of interspersed messages.

Changelog:

This was original a single patch but was expanded into a series.

v1: https://lore.kernel.org/lkml/20221121050946.3540-1-linux@weissschuh.net/
v1 -> v2:
  * Introduce new pr_<level>_cont() macros in printk.h
  * Add checkpatch.pl validation

Thomas Weißschuh (3):
  printk: introduce new macros pr_<level>_cont()
  checkpatch: handle new pr_<level>_cont macros
  power: process: use explicit levels for printk continuations

 include/linux/printk.h | 23 +++++++++++++++++++++++
 kernel/power/process.c | 18 +++++++++---------
 scripts/checkpatch.pl  | 10 ++++++++--
 3 files changed, 40 insertions(+), 11 deletions(-)


base-commit: 0b1dcc2cf55ae6523c6fbd0d741b3ac28c9f4536
  

On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
>
> This series adds new printk wrapper macros pr_<level>_cont().
> These create continuation messages with an explicit level.
>
> Explicit levels are useful when a continuation message is split from its main
> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
> which can lead to stray partial log messages when filtering by level.
>
> Also checkpatch is modified to recommend the new macros over plain pr_cont().
>
> Lastly the new macros are used in kernel/power/process.c as this file uses
> continuation messages during system suspend-resume which creates a high
> likelyhood of interspersed messages.

Well, if process.c is the only problematic piece of code in this
respect, I'm not sure if adding the new infrastructure for its benefit
alone is worth it, because it can very well do without pr_cont() at
all.

Please see the patch below (compiled only, sorry for gmail-induced
white space damage).  I'll submit it properly later if it works for
everyone.

---
 kernel/power/process.c |   25 ++++++++++---------------
 1 file changed, 10 insertions(+), 15 deletions(-)

Index: linux-pm/kernel/power/process.c
===================================================================
--- linux-pm.orig/kernel/power/process.c
+++ linux-pm/kernel/power/process.c
@@ -27,6 +27,8 @@ unsigned int __read_mostly freeze_timeou

 static int try_to_freeze_tasks(bool user_only)
 {
+    const char *what = user_only ? "user space processes" :
+                    "remaining freezable tasks";
     struct task_struct *g, *p;
     unsigned long end_time;
     unsigned int todo;
@@ -36,6 +38,8 @@ static int try_to_freeze_tasks(bool user
     bool wakeup = false;
     int sleep_usecs = USEC_PER_MSEC;

+    pr_info("Freezing %s\n", what);
+
     start = ktime_get_boottime();

     end_time = jiffies + msecs_to_jiffies(freeze_timeout_msecs);
@@ -82,9 +86,8 @@ static int try_to_freeze_tasks(bool user
     elapsed_msecs = ktime_to_ms(elapsed);

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

     return todo ? -EBUSY : 0;
@@ -130,14 +133,11 @@ int freeze_processes(void)
         static_branch_inc(&freezer_active);

     pm_wakeup_clear(0);
-    pr_info("Freezing user space processes ... ");
     pm_freezing = true;
     error = try_to_freeze_tasks(true);
-    if (!error) {
+    if (!error)
         __usermodehelper_set_disable_depth(UMH_DISABLED);
-        pr_cont("done.");
-    }
-    pr_cont("\n");
+
     BUG_ON(in_atomic());

     /*
@@ -166,14 +166,9 @@ int freeze_kernel_threads(void)
 {
     int error;

-    pr_info("Freezing remaining freezable tasks ... ");
-
     pm_nosig_freezing = true;
     error = try_to_freeze_tasks(false);
-    if (!error)
-        pr_cont("done.");

-    pr_cont("\n");
     BUG_ON(in_atomic());

     if (error)
  

On 2022-11-30 18:57+0100, Rafael J. Wysocki wrote:
> On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
>>
>> This series adds new printk wrapper macros pr_<level>_cont().
>> These create continuation messages with an explicit level.
>>
>> Explicit levels are useful when a continuation message is split from its main
>> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
>> which can lead to stray partial log messages when filtering by level.
>>
>> Also checkpatch is modified to recommend the new macros over plain pr_cont().
>>
>> Lastly the new macros are used in kernel/power/process.c as this file uses
>> continuation messages during system suspend-resume which creates a high
>> likelyhood of interspersed messages.
> 
> Well, if process.c is the only problematic piece of code in this
> respect, I'm not sure if adding the new infrastructure for its benefit
> alone is worth it, because it can very well do without pr_cont() at
> all.

In general all usages of pr_cont() are problematic.
Any continuation can be split from its main message, leading to misleved
continuations.
process.c is just the one that I noticed reliably hitting this problem on my
machine.

> Please see the patch below (compiled only, sorry for gmail-induced
> white space damage).  I'll submit it properly later if it works for
> everyone.

The patch looks fine to me and getting rid of usages of pr_cont() seems to be
the better aproach where it is possible.

Petr: do you still want me to submit the new macros even if it is not used
directly anymore?

> ---
>  kernel/power/process.c |   25 ++++++++++---------------
>  1 file changed, 10 insertions(+), 15 deletions(-)
> 
> Index: linux-pm/kernel/power/process.c
> ===================================================================
> --- linux-pm.orig/kernel/power/process.c
> +++ linux-pm/kernel/power/process.c
> @@ -27,6 +27,8 @@ unsigned int __read_mostly freeze_timeou
> 
>  static int try_to_freeze_tasks(bool user_only)
>  {
> +    const char *what = user_only ? "user space processes" :
> +                    "remaining freezable tasks";
>      struct task_struct *g, *p;
>      unsigned long end_time;
>      unsigned int todo;
> @@ -36,6 +38,8 @@ static int try_to_freeze_tasks(bool user
>      bool wakeup = false;
>      int sleep_usecs = USEC_PER_MSEC;
> 
> +    pr_info("Freezing %s\n", what);
> +
>      start = ktime_get_boottime();
> 
>      end_time = jiffies + msecs_to_jiffies(freeze_timeout_msecs);
> @@ -82,9 +86,8 @@ static int try_to_freeze_tasks(bool user
>      elapsed_msecs = ktime_to_ms(elapsed);
> 
>      if (todo) {
> -        pr_cont("\n");
> -        pr_err("Freezing of tasks %s after %d.%03d seconds "
> -               "(%d tasks refusing to freeze, wq_busy=%d):\n",
> +        pr_err("Freezing %s %s after %d.%03d seconds "
> +               "(%d tasks refusing to freeze, wq_busy=%d):\n", what,
>                 wakeup ? "aborted" : "failed",
>                 elapsed_msecs / 1000, elapsed_msecs % 1000,
>                 todo - wq_busy, wq_busy);
> @@ -101,8 +104,8 @@ static int try_to_freeze_tasks(bool user
>              read_unlock(&tasklist_lock);
>          }
>      } else {
> -        pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
> -            elapsed_msecs % 1000);
> +        pr_info("Freezing %s completed (elapsed %d.%03d seconds)\n",
> +            what, elapsed_msecs / 1000, elapsed_msecs % 1000);
>      }
> 
>      return todo ? -EBUSY : 0;
> @@ -130,14 +133,11 @@ int freeze_processes(void)
>          static_branch_inc(&freezer_active);
> 
>      pm_wakeup_clear(0);
> -    pr_info("Freezing user space processes ... ");
>      pm_freezing = true;
>      error = try_to_freeze_tasks(true);
> -    if (!error) {
> +    if (!error)
>          __usermodehelper_set_disable_depth(UMH_DISABLED);
> -        pr_cont("done.");
> -    }
> -    pr_cont("\n");
> +
>      BUG_ON(in_atomic());
> 
>      /*
> @@ -166,14 +166,9 @@ int freeze_kernel_threads(void)
>  {
>      int error;
> 
> -    pr_info("Freezing remaining freezable tasks ... ");
> -
>      pm_nosig_freezing = true;
>      error = try_to_freeze_tasks(false);
> -    if (!error)
> -        pr_cont("done.");
> 
> -    pr_cont("\n");
>      BUG_ON(in_atomic());
> 
>      if (error)
  

On Thu 2022-12-01 00:37:15, Thomas Weißschuh wrote:
> On 2022-11-30 18:57+0100, Rafael J. Wysocki wrote:
> > On Fri, Nov 25, 2022 at 8:10 PM Thomas Weißschuh <linux@weissschuh.net> wrote:
> >>
> >> This series adds new printk wrapper macros pr_<level>_cont().
> >> These create continuation messages with an explicit level.
> >>
> >> Explicit levels are useful when a continuation message is split from its main
> >> message. Without the explicit level KERN_DEFAULT ("warn" by default) is used
> >> which can lead to stray partial log messages when filtering by level.
> >>
> >> Also checkpatch is modified to recommend the new macros over plain pr_cont().
> >>
> >> Lastly the new macros are used in kernel/power/process.c as this file uses
> >> continuation messages during system suspend-resume which creates a high
> >> likelyhood of interspersed messages.
> > 
> > Well, if process.c is the only problematic piece of code in this
> > respect, I'm not sure if adding the new infrastructure for its benefit
> > alone is worth it, because it can very well do without pr_cont() at
> > all.
> 
> In general all usages of pr_cont() are problematic.
> Any continuation can be split from its main message, leading to misleved
> continuations.

In most cases this happens "only" when a message from another CPU
or interrupt context is printed in parallel.

> process.c is just the one that I noticed reliably hitting this problem on my
> machine.

The situation in process.c was even worse. The error message was
printed in the middle of the to-be-continued message. As a result,
the loglevel of the pr_cont() part was always (reliably) broken
when the error message was printed.


> > Please see the patch below (compiled only, sorry for gmail-induced
> > white space damage).  I'll submit it properly later if it works for
> > everyone.
> 
> The patch looks fine to me and getting rid of usages of pr_cont() seems to be
> the better aproach where it is possible.

I agree. It is always better to avoid pr_cont() when possible.

> Petr: do you still want me to submit the new macros even if it is not used
> directly anymore?

Good question. In general, new API should not be added if there is
no user. So, I would prefer to do not add the API if the problem
will be fixed without it.

Best Regards,
Petr