Skip to contentSkip to conversation

printk: introduce new macros pr_<level>_cont()

PATCH In review Thomas Weißschuh 4 participants 20 messages Nov 25, 2022 – Dec 2, 2022

Subsystems (4)
Suspend to RAM Hibernation Checkpatch Printk
lore
Share & tools
lore

Thomas Weißschuh

author
#0 lore raw

v2 cover 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/[email protected]/
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

Signature · 1 line
2.38.1
author
#1 lore raw

PATCH v2 1/3 printk: introduce new macros pr_<level>_cont()

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +23 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
+
 extern const struct file_operations kmsg_fops;
 
 enum {
Signature · 1 line
2.38.1
maintainer
#2 lore raw
Quoted 27 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +2 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

include/linux/printk.h do { \ · line 712

Quoted 10 lines
include/linux/printk.h +7 -0
@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

Quoted 17 lines
include/linux/printk.h +14 -0
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
+
 extern const struct file_operations kmsg_fops;
 
 enum {
author
#3 lore raw
Quoted 31 lines · Joe Perches
Quoted 30 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +2 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
Quoted 10 lines

include/linux/printk.h do { \ · line 712

Quoted 7 lines
include/linux/printk.h +7 -0
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

If nobody else disagrees I'll do this for v3.

Quoted 18 lines
Quoted 17 lines
include/linux/printk.h +14 -0
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */
+
 extern const struct file_operations kmsg_fops;
 
 enum {
maintainer
#4 lore raw
Quoted 26 lines · Thomas Weißschuh
Quoted 14 lines · Joe Perches
Quoted 13 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

include/linux/printk.h +0 -0
@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
Quoted 10 lines

include/linux/printk.h do { \ · line 712

Quoted 7 lines
include/linux/printk.h +7 -0
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

Quoted 1 line

If nobody else disagrees I'll do this for v3.

I slightly prefer the way how it is now. IMHO, it makes it easier to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:

<6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... " <6,c> kernel/power/process.c:218 thaw_processes "done.\n"
<6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
<6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
<6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
<6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... " <6,c> kernel/power/process.c:140 freeze_processes "\n"
<6,c> kernel/power/process.c:138 freeze_processes "done."
<6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... " <6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "

That said, I do not want to fight over it. It is hidden behind the API. The only really visible place is the printk index.

[*] The index is available only when CONFIG_PRINTK_INDEX is enabled.

Best Regards,
Petr

author
#5 lore raw
Quoted 32 lines · Petr Mladek
Quoted 26 lines · Thomas Weißschuh
Quoted 14 lines · Joe Perches
Quoted 13 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

include/linux/printk.h +0 -0
@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
Quoted 10 lines

include/linux/printk.h do { \ · line 712

Quoted 7 lines
include/linux/printk.h +7 -0
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

Quoted 1 line

If nobody else disagrees I'll do this for v3.

I slightly prefer the way how it is now. IMHO, it makes it easier to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:

Quoted 10 lines

<6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... " <6,c> kernel/power/process.c:218 thaw_processes "done.\n"
<6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
<6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
<6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
<6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... " <6,c> kernel/power/process.c:140 freeze_processes "\n"
<6,c> kernel/power/process.c:138 freeze_processes "done."
<6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... " <6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "

I did not test it (will do so later) but it seems to me that the code in kernel/printk/index.c should do this correctly in either case. At least it tries to:

if (flags & LOG_CONT) {
	/*
	 * LOGLEVEL_DEFAULT here means "use the same level as the
	 * message we're continuing from", not the default message
	 * loglevel, so don't display it as such.
	 */
	if (level == LOGLEVEL_DEFAULT)
		seq_puts(s, "<c>");
		else
		seq_printf(s, "<%d,c>", level);
	} else
		seq_printf(s, "<%d>", level);
	}
}

I'll try to validate it.

If it doesn't work it may make more sense to fix the index file generation. What do you think

Quoted 7 lines

That said, I do not want to fight over it. It is hidden behind the API. The only really visible place is the printk index.

[*] The index is available only when CONFIG_PRINTK_INDEX is enabled.

Best Regards,
Petr

Thomas

maintainer
#6 lore raw
Quoted 48 lines · Thomas Weißschuh
Quoted 32 lines · Petr Mladek
Quoted 26 lines · Thomas Weißschuh
Quoted 14 lines · Joe Perches
Quoted 13 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

include/linux/printk.h +0 -0
@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
Quoted 10 lines

include/linux/printk.h do { \ · line 712

Quoted 7 lines
include/linux/printk.h +7 -0
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Aren't this rather backwards?
KERN_CONT KERN_<LEVEL> seems to make more sense to me.

Quoted 1 line

If nobody else disagrees I'll do this for v3.

I slightly prefer the way how it is now. IMHO, it makes it easier to check the related levels in /sys/kernel/debug/printk/index/vmlinux [*]:

Quoted 10 lines

<6> kernel/power/process.c:227 thaw_kernel_threads "Restarting kernel threads ... " <6,c> kernel/power/process.c:218 thaw_processes "done.\n"
<6> kernel/power/process.c:197 thaw_processes "Restarting tasks ... "
<6,c> kernel/power/process.c:176 freeze_kernel_threads "\n"
<6,c> kernel/power/process.c:174 freeze_kernel_threads "done."
<6> kernel/power/process.c:169 freeze_kernel_threads "Freezing remaining freezable tasks ... " <6,c> kernel/power/process.c:140 freeze_processes "\n"
<6,c> kernel/power/process.c:138 freeze_processes "done."
<6> kernel/power/process.c:133 freeze_processes "Freezing user space processes ... " <6,c> kernel/power/process.c:105 try_to_freeze_tasks "(elapsed %d.%03d seconds) "

I did not test it (will do so later) but it seems to me that the code in kernel/printk/index.c should do this correctly in either case. At least it tries to:

Quoted 13 lines
if (flags & LOG_CONT) {
	/*
	 * LOGLEVEL_DEFAULT here means "use the same level as the
	 * message we're continuing from", not the default message
	 * loglevel, so don't display it as such.
	 */
	if (level == LOGLEVEL_DEFAULT)
		seq_puts(s, "<c>");
		else
		seq_printf(s, "<%d,c>", level);
	} else
		seq_printf(s, "<%d>", level);
	}

Great. It makes the index consistent. I should have checked the code ;-)

I do not mind then about the ordering in the macro definitions. It really seems to be only an implementation detail.

Best Regards,
Petr

maintainer
#7 lore raw
In reply to Thomas Weißschuh
Quoted 40 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +12 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\

include/linux/printk.h do { \ · line 725

Quoted 10 lines
include/linux/printk.h +10 -0
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */

I guess that you wanted to write "pr_debug_cont".

Also I am not sure what you mean with "doesn't make sense". IMHO, it might make sense. But it would be hard to use and error prone with CONFIG_DYNAMIC_DEBUG.

And more importantly, it probably would not work properly. If I get it corretly the dynamic debug messages are printed by the wrapper:

void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) {
[...]

	vaf.fmt = fmt;
	vaf.va = &args;

	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);

[...]

This clearly does not support KERN_CONT in "fmt".

I suggest to either remove the comment completely. Or write something like:

/* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */

Best Regards,
Petr

author
#8 lore raw
Quoted 45 lines · Petr Mladek
Quoted 44 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +16 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
Quoted 8 lines

include/linux/printk.h do { \ · line 725

Quoted 6 lines
include/linux/printk.h +6 -0
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */

I guess that you wanted to write "pr_debug_cont".

Indeed.

Quoted 10 lines

Also I am not sure what you mean with "doesn't make sense". IMHO, it might make sense. But it would be hard to use and error prone with CONFIG_DYNAMIC_DEBUG.

And more importantly, it probably would not work properly. If I get it corretly the dynamic debug messages are printed by the wrapper:

void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) {
[...]

Quoted 7 lines
	vaf.fmt = fmt;
	vaf.va = &args;

	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);

[...]

This clearly does not support KERN_CONT in "fmt".

Good point.

My doubt was more that it would force users to know which message continuations belong together and always enable all of them together with dynamic debug.
Which would be very errorprone and annoying to use.

But if it doesn't work at all that's an even stronger point.

Quoted 4 lines

I suggest to either remove the comment completely. Or write something like:

/* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */

What about:

/* no pr_debug_cont(), it's errorprone to use
* and can't be supported easily with CONFIG_DYNAMIC_DEBUG */

Thomas

maintainer
#9 lore raw
Quoted 73 lines · Thomas Weißschuh
Quoted 45 lines · Petr Mladek
Quoted 44 lines · Thomas Weißschuh

These macros emit continuation messages with explicit levels. In case the continuation is logged separately from the original message it will retain its level instead of falling back to KERN_DEFAULT.

This remedies the issue that logs filtered by level contain stray continuation messages without context.

Suggested-by Petr Mladek <[email protected]>
Signed-off-by Thomas Weißschuh <[email protected]>
---
 include/linux/printk.h | 23 +++++++++++++++++++++++
 1 file changed, 23 insertions(+)
include/linux/printk.h +16 -0
index 8c81806c2e99..8f564c38f121 100644
@@ -537,6 +537,8 @@ struct pi_entry {
  * This macro expands to a printk with KERN_CONT loglevel. It should only be
  * used when continuing a log message with no newline ('\n') enclosed. Otherwise
  * it defaults back to KERN_DEFAULT loglevel.
+ *
+ * Use the dedicated pr_<level>_cont() macros instead.
  */
 #define pr_cont(fmt, ...) \
 	printk(KERN_CONT fmt, ##__VA_ARGS__)

@@ -701,6 +703,27 @@ do {									\
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Print a continuation message with level. In case the continuation is split
+ * from the main message it preserves the level.
+ */
+
+#define pr_emerg_cont(fmt, ...)					\
+	printk(KERN_EMERG KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_alert_cont(fmt, ...)					\
+	printk(KERN_ALERT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_crit_cont(fmt, ...)					\
+	printk(KERN_CRIT KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_err_cont(fmt, ...)					\
+	printk(KERN_ERR KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_warn_cont(fmt, ...)					\
Quoted 8 lines

include/linux/printk.h do { \ · line 725

Quoted 6 lines
include/linux/printk.h +6 -0
+	printk(KERN_WARN KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_notice_cont(fmt, ...)					\
+	printk(KERN_NOTICE KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+#define pr_info_cont(fmt, ...)					\
+	printk(KERN_INFO KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)
+/* no pr_debug_ratelimited, it doesn't make sense with CONFIG_DYNAMIC_DEBUG. */

I guess that you wanted to write "pr_debug_cont".

Indeed.

Quoted 16 lines

Also I am not sure what you mean with "doesn't make sense". IMHO, it might make sense. But it would be hard to use and error prone with CONFIG_DYNAMIC_DEBUG.

And more importantly, it probably would not work properly. If I get it corretly the dynamic debug messages are printed by the wrapper:

void __dynamic_pr_debug(struct _ddebug *descriptor, const char *fmt, ...) {
[...]

	vaf.fmt = fmt;
	vaf.va = &args;

	printk(KERN_DEBUG "%s%pV", dynamic_emit_prefix(descriptor, buf), &vaf);

[...]

Quoted 8 lines
Quoted 1 line

This clearly does not support KERN_CONT in "fmt".

Good point.

My doubt was more that it would force users to know which message continuations belong together and always enable all of them together with dynamic debug.
Which would be very errorprone and annoying to use.

Yes. This is what I meant with "hard to use" but I was not clear enough :-)

Quoted 6 lines

But if it doesn't work at all that's an even stronger point.

Quoted 3 lines

I suggest to either remove the comment completely. Or write something like:

Quoted 6 lines
Quoted 1 line

/* no pr_debug_cont(), can't be supported easily with CONFIG_DYNAMIC_DEBUG */

What about:

/* no pr_debug_cont(), it's errorprone to use
* and can't be supported easily with CONFIG_DYNAMIC_DEBUG */

Sounds good to me.

Best Regards,
Petr

PS: Heh, I just realized that we actually abandoned these changes because
the continuous lines in kernel/power/process.c are going to be removed. (/me doing too many things in parallel).

Anyway, it is possible that someone would take this patches to fix another continuous lines in the future.

author
#10 lore raw

PATCH v2 2/3 checkpatch: handle new pr_<level>_cont macros

In reply to Thomas Weißschuh

These new macros from include/linux/printk.h replace the usage of plain pr_cont().

Signed-off-by Thomas Weißschuh <[email protected]>
---
 scripts/checkpatch.pl | 10 ++++++++--
 1 file changed, 8 insertions(+), 2 deletions(-)
scripts/checkpatch.pl +8 -2
index 1e5e66ae5a52..fb1747639c9c 100755
@@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
 
 our $logFunctions = qr{(?x:
 	printk(?:_ratelimited|_once|_deferred_once|_deferred|)|
-	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|)|
+	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|_cont|)|
 	TP_printk|
 	WARN(?:_RATELIMIT|_ONCE|)|
 	panic|

@@ -6374,11 +6374,17 @@ sub process {
 		}
 
 # check for logging continuations
-		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
+		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_([a-z]+_)?cont\s*\(/) {
 			WARN("LOGGING_CONTINUATION",
 			     "Avoid logging continuation uses where feasible\n" . $herecurr);
 		}
 
+# check for logging continuations without explicit level
+		if ($line =~ /\bpr_cont\s*\(/) {
+			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
+			     "Avoid logging continuation without level\n" . $herecurr);
+		}
+
 # check for unnecessary use of %h[xudi] and %hh[xudi] in logging functions
 		if (defined $stat &&
 		    $line =~ /\b$logFunctions\s*\(/ &&
Signature · 1 line
2.38.1
maintainer
#11 lore raw

Re: [PATCH v2 2/3] checkpatch: handle new pr_<level>_cont macros

Quoted 2 lines · Thomas Weißschuh

These new macros from include/linux/printk.h replace the usage of plain pr_cont().

[]

scripts/checkpatch.pl our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b}; · line 593

Quoted 10 lines
scripts/checkpatch.pl +1 -1
index 1e5e66ae5a52..fb1747639c9c 100755
@@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
 
 our $logFunctions = qr{(?x:
 	printk(?:_ratelimited|_once|_deferred_once|_deferred|)|
-	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|)|
+	(?:[a-z0-9]+_){1,2}(?:printk|emerg|alert|crit|err|warning|warn|notice|info|debug|dbg|vdbg|devel|cont|WARN)(?:_ratelimited|_once|_cont|)|

OK

scripts/checkpatch.pl sub process { · line 6380

Quoted 12 lines
scripts/checkpatch.pl +1 -1
 	TP_printk|
 	WARN(?:_RATELIMIT|_ONCE|)|
 	panic|

@@ -6374,11 +6374,17 @@ sub process {
 		}
 
 # check for logging continuations
-		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_cont\s*\(/) {
+		if ($line =~ /\bprintk\s*\(\s*KERN_CONT\b|\bpr_([a-z]+_)?cont\s*\(/) {
 			WARN("LOGGING_CONTINUATION",
 			     "Avoid logging continuation uses where feasible\n" . $herecurr);
 		}

OK

scripts/checkpatch.pl sub process { · line 6387

Quoted 6 lines
scripts/checkpatch.pl +6 -0
+# check for logging continuations without explicit level
+		if ($line =~ /\bpr_cont\s*\(/) {
+			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
+			     "Avoid logging continuation without level\n" . $herecurr);
+		}
+

Not so sure about this one.

I think relatively few situations are going to require interleaving avoidance.

Quoted 3 lines
scripts/checkpatch.pl +0 -0
 # check for unnecessary use of %h[xudi] and %hh[xudi] in logging functions
 		if (defined $stat &&
 		    $line =~ /\b$logFunctions\s*\(/ &&
maintainer
#12 lore raw

Re: [PATCH v2 2/3] checkpatch: handle new pr_<level>_cont macros

Quoted 16 lines · Joe Perches
Quoted 2 lines · Thomas Weißschuh

These new macros from include/linux/printk.h replace the usage of plain pr_cont().

[]

scripts/checkpatch.pl our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b}; · line 595

Quoted 9 lines
scripts/checkpatch.pl +6 -0
@@ -590,7 +590,7 @@ our $zero_initializer = qr{(?:(?:0[xX])?0+$Int_type?|NULL|false)\b};
+# check for logging continuations without explicit level
+		if ($line =~ /\bpr_cont\s*\(/) {
+			WARN("LOGGING_CONTINUATION_WITHOUT_LEVEL",
+			     "Avoid logging continuation without level\n" . $herecurr);
+		}
+

Not so sure about this one.

Quoted 1 line

I think relatively few situations are going to require interleaving avoidance.

Well, the problem is generic and any pr_cont() is affected except for NMI context on single CPU system.

I though about a generic solution. We could store the last used printk log level per-process and per-CPU context. But it does not solve the situation when an unrelated printk() is printed by a nested function.

It is exactly the case with try_to_freeze_tasks() in the 3rd patch. Simplified code:

int freeze_processes(void)

{
	pr_info("Freezing user space processes ... ");
	try_to_freeze_tasks(true);
	pr_info_cont("done.");
}

, where

static int try_to_freeze_tasks(bool user_only)
{
[...]

	if (todo) {
		pr_err("Freezing of tasks %s after %d.%03d seconds "

[...]
}

I would personally add this check into checkpatch.pl. It might help to make people aware about that pr_cont() is just the best effort.

Best Regards,
Petr

author
#13 lore raw

PATCH v2 3/3 power: process: use explicit levels for printk continuations

In reply to Thomas Weißschuh

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 | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)
kernel/power/process.c +9 -9
index ddd9988327fe..698a823033e4 100644
@@ -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_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,8 +101,8 @@ static int try_to_freeze_tasks(bool user_only)
 			read_unlock(&tasklist_lock);
 		}
 	} else {
-		pr_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
-			elapsed_msecs % 1000);
+		pr_info_cont("(elapsed %d.%03d seconds) ", elapsed_msecs / 1000,
+			     elapsed_msecs % 1000);
 	}
 
 	return todo ? -EBUSY : 0;

@@ -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_cont("done.");
 	}
-	pr_cont("\n");
+	pr_info_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_cont("done.");
 
-	pr_cont("\n");
+	pr_info_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_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_cont("done.\n");
 }
Signature · 1 line
2.38.1
maintainer
#14 lore raw

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

kernel/power/process.c

Quoted 23 lines · Thomas Weißschuh

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 | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)
kernel/power/process.c +0 -0

[]

kernel/power/process.c static int try_to_freeze_tasks(bool user_only) · line 85

Quoted 6 lines
kernel/power/process.c +1 -1
@@ -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_cont("\n");

I think this isn't needed because of the immediately following pr_err.

Quoted 3 lines
kernel/power/process.c +0 -0
 		pr_err("Freezing of tasks %s after %d.%03d seconds "
 		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
 		       wakeup ? "aborted" : "failed",
author
#15 lore raw

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

Quoted 25 lines · Joe Perches

kernel/power/process.c

Quoted 23 lines · Thomas Weißschuh

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 | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)
kernel/power/process.c +0 -0

[]

Quoted 8 lines

kernel/power/process.c static int try_to_freeze_tasks(bool user_only) · line 85

Quoted 6 lines
kernel/power/process.c +1 -1
@@ -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_cont("\n");

I think this isn't needed because of the immediately following pr_err.

The pr_cont() itself or the conversion to pr_info_cont() is not needed?

Personally I would prefer to keep the patch as is.

If only the conversion is not needed for consistency with the rest of the file. If the pr_cont() in general is not needed it should be changed in a dedicated patch (by somebody who knows this code better).

Quoted 4 lines
Quoted 3 lines
kernel/power/process.c +0 -0
 		pr_err("Freezing of tasks %s after %d.%03d seconds "
 		       "(%d tasks refusing to freeze, wq_busy=%d):\n",
 		       wakeup ? "aborted" : "failed",
maintainer
#16 lore raw

Re: [PATCH v2 3/3] power: process: use explicit levels for printk continuations

Quoted 26 lines · Thomas Weißschuh
Quoted 25 lines · Joe Perches

kernel/power/process.c

Quoted 23 lines · Thomas Weißschuh

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 | 18 +++++++++---------
 1 file changed, 9 insertions(+), 9 deletions(-)
kernel/power/process.c +0 -0

[]

Quoted 8 lines
Quoted 8 lines

kernel/power/process.c static int try_to_freeze_tasks(bool user_only) · line 85

Quoted 6 lines
kernel/power/process.c +1 -1
@@ -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_cont("\n");

I think this isn't needed because of the immediately following pr_err.

Great catch.

Quoted 1 line

The pr_cont() itself or the conversion to pr_info_cont() is not needed?

The pr_cont() was needed before the commit 4bcc595ccd80decb42450 ("printk: reinstate KERN_CONT for printing continuation lines").

Before this commit, lines were appended even without KERN_CONT when the previous line did not end with "\n".

The above commit caused that only lines with KERN_CONT will be appended.

We have the code:

		pr_cont("\n");
		pr_err("Freezing of tasks %s after %d.%03d seconds "

The pr_cont() is not needed here because pr_err() does not have KERN_CONT. It will always start on a new line.

Quoted 5 lines

Personally I would prefer to keep the patch as is.

If only the conversion is not needed for consistency with the rest of the file. If the pr_cont() in general is not needed it should be changed in a dedicated patch (by somebody who knows this code better).

I agree that it should be removed in a separate patch. The commit message should mention the commit that modified the KERN_CONT handling.

Best Regards,
Petr

maintainer
#17 lore raw
In reply to Thomas Weißschuh
Quoted 8 lines · Thomas Weißschuh

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.

Quoted 5 lines

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(-)
kernel/power/process.c +10 -15
Index: 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)
author
#18 lore raw
Quoted 11 lines · Rafael J. Wysocki
Quoted 10 lines · Thomas Weißschuh

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().

Quoted 8 lines
Quoted 3 lines

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.

Quoted 3 lines

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?

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

Index: linux-pm/kernel/power/process.c
===================================================================

kernel/power/process.c +10 -15
@@ -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)
maintainer
#19 lore raw
Quoted 16 lines · Thomas Weißschuh
Quoted 15 lines · Rafael J. Wysocki
Quoted 13 lines · Thomas Weißschuh

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.

Quoted 8 lines
Quoted 4 lines

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.

Quoted 2 lines

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.

Quoted 6 lines
Quoted 3 lines

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.

Quoted 2 lines

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