| Message ID | 20221125190948.2062-1-linux@weissschuh.net (mailing list archive) |
|---|---|
| Headers | show |
| Series | printk: introduce new macros pr_<level>_cont() | expand |
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
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