[PATCH 1/2] printk: Refactor processing of line severity tokens

[PATCH 1/2] printk: Refactor processing of line severity tokens

[Nick Andrew]

printk: Refactor processing of line severity tokens

Restructure the logic of vprintk() so the processing of the leading
3 characters of each input line is in one place, regardless whether
printk_time is enabled. This makes the code smaller and easier to
understand.

Signed-off-by: Nick Andrew <nick@nick-andrew.net>
---

 kernel/printk.c |   63 +++++++++++++++++++++++++------------------------------
 1 files changed, 29 insertions(+), 34 deletions(-)


diff --git a/kernel/printk.c b/kernel/printk.c
index c46a20a..bca9359 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -656,11 +656,12 @@ static int printk_recursion_bug;
 
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
-	static int log_level_unknown = 1;
+	static int new_text_line = 1;
 	static char printk_buf[1024];
 
-	unsigned long flags;
 	int printed_len = 0;
+	int current_log_level = default_message_loglevel;
+	unsigned long flags;
 	int this_cpu;
 	char *p;
 
@@ -702,61 +703,55 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	printed_len += vscnprintf(printk_buf + printed_len,
 				  sizeof(printk_buf) - printed_len, fmt, args);
 
+
 	/*
 	 * Copy the output into log_buf.  If the caller didn't provide
 	 * appropriate log level tags, we insert them here
 	 */
 	for (p = printk_buf; *p; p++) {
-		if (log_level_unknown) {
-                        /* log_level_unknown signals the start of a new line */
+		if (new_text_line) {
+			/* If a token, set current_log_level and skip over */
+			if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
+			    p[2] == '>') {
+				current_log_level = p[1] - '0';
+				p += 3;
+				printed_len -= 3;
+			} else {
+				current_log_level = default_message_loglevel;
+			}
+
+			/* Always output the token */
+			emit_log_char('<');
+			emit_log_char(current_log_level + '0');
+			emit_log_char('>');
+			printed_len += 3;
+			new_text_line = 0;
+
 			if (printk_time) {
-				int loglev_char;
+				/* Follow the token with the time */
 				char tbuf[50], *tp;
 				unsigned tlen;
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				/*
-				 * force the log level token to be
-				 * before the time output.
-				 */
-				if (p[0] == '<' && p[1] >='0' &&
-				   p[1] <= '7' && p[2] == '>') {
-					loglev_char = p[1];
-					p += 3;
-					printed_len -= 3;
-				} else {
-					loglev_char = default_message_loglevel
-						+ '0';
-				}
 				t = cpu_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf,
-						"<%c>[%5lu.%06lu] ",
-						loglev_char,
-						(unsigned long)t,
-						nanosec_rem/1000);
+				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+						(unsigned long) t,
+						nanosec_rem / 1000);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
 				printed_len += tlen;
-			} else {
-				if (p[0] != '<' || p[1] < '0' ||
-				   p[1] > '7' || p[2] != '>') {
-					emit_log_char('<');
-					emit_log_char(default_message_loglevel
-						+ '0');
-					emit_log_char('>');
-					printed_len += 3;
-				}
 			}
-			log_level_unknown = 0;
+
 			if (!*p)
 				break;
 		}
+
 		emit_log_char(*p);
 		if (*p == '\n')
-			log_level_unknown = 1;
+			new_text_line = 1;
 	}
 
 	/*

[PATCH 2/2] printk: Remember the message level for multi-line output

[Nick Andrew]

printk: Remember the message level for multi-line output

    printk(KERN_ALERT "Danger Will Robinson!\nAlien Approaching!\n");

At present this will result in one message at ALERT level and one
at the current default message loglevel (e.g. WARNING). This is
non-intuitive.

Modify vprintk() to remember the message loglevel each time it
is specified and use it for subsequent lines of output which do
not specify one, within the same call to printk.

Signed-off-by: Nick Andrew <nick@nick-andrew.net>
---

 kernel/printk.c |    2 --
 1 files changed, 0 insertions(+), 2 deletions(-)


diff --git a/kernel/printk.c b/kernel/printk.c
index bca9359..5c97eb1 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -716,8 +716,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 				current_log_level = p[1] - '0';
 				p += 3;
 				printed_len -= 3;
-			} else {
-				current_log_level = default_message_loglevel;
 			}
 
 			/* Always output the token */

[PATCH 1/2] printk: Refactor processing of line severity tokens

[Nick Andrew]

printk: Refactor processing of line severity tokens

Restructure the logic of vprintk() so the processing of the leading
3 characters of each input line is in one place, regardless whether
printk_time is enabled. This makes the code smaller and easier to
understand.

Signed-off-by: Nick Andrew <nick@nick-andrew.net>
---
This is the third revision.

  rev 1 - initial patch, refactor + remember current_log_level
  rev 2 - split into 2 parts
  rev 3 - I realised that rev 2 is inefficient; all I had to do was move
          the declaration of current_log_level, to alter the memory
	  behaviour.

 kernel/printk.c |   61 ++++++++++++++++++++++++-------------------------------
 1 files changed, 27 insertions(+), 34 deletions(-)


diff --git a/kernel/printk.c b/kernel/printk.c
index c46a20a..02ca845 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -656,11 +656,11 @@ static int printk_recursion_bug;
 
 asmlinkage int vprintk(const char *fmt, va_list args)
 {
-	static int log_level_unknown = 1;
+	static int new_text_line = 1;
 	static char printk_buf[1024];
 
-	unsigned long flags;
 	int printed_len = 0;
+	unsigned long flags;
 	int this_cpu;
 	char *p;
 
@@ -702,61 +702,54 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	printed_len += vscnprintf(printk_buf + printed_len,
 				  sizeof(printk_buf) - printed_len, fmt, args);
 
+
 	/*
 	 * Copy the output into log_buf.  If the caller didn't provide
 	 * appropriate log level tags, we insert them here
 	 */
 	for (p = printk_buf; *p; p++) {
-		if (log_level_unknown) {
-                        /* log_level_unknown signals the start of a new line */
+		if (new_text_line) {
+			int current_log_level = default_message_loglevel;
+			/* If a token, set current_log_level and skip over */
+			if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
+			    p[2] == '>') {
+				current_log_level = p[1] - '0';
+				p += 3;
+				printed_len -= 3;
+			}
+
+			/* Always output the token */
+			emit_log_char('<');
+			emit_log_char(current_log_level + '0');
+			emit_log_char('>');
+			printed_len += 3;
+			new_text_line = 0;
+
 			if (printk_time) {
-				int loglev_char;
+				/* Follow the token with the time */
 				char tbuf[50], *tp;
 				unsigned tlen;
 				unsigned long long t;
 				unsigned long nanosec_rem;
 
-				/*
-				 * force the log level token to be
-				 * before the time output.
-				 */
-				if (p[0] == '<' && p[1] >='0' &&
-				   p[1] <= '7' && p[2] == '>') {
-					loglev_char = p[1];
-					p += 3;
-					printed_len -= 3;
-				} else {
-					loglev_char = default_message_loglevel
-						+ '0';
-				}
 				t = cpu_clock(printk_cpu);
 				nanosec_rem = do_div(t, 1000000000);
-				tlen = sprintf(tbuf,
-						"<%c>[%5lu.%06lu] ",
-						loglev_char,
-						(unsigned long)t,
-						nanosec_rem/1000);
+				tlen = sprintf(tbuf, "[%5lu.%06lu] ",
+						(unsigned long) t,
+						nanosec_rem / 1000);
 
 				for (tp = tbuf; tp < tbuf + tlen; tp++)
 					emit_log_char(*tp);
 				printed_len += tlen;
-			} else {
-				if (p[0] != '<' || p[1] < '0' ||
-				   p[1] > '7' || p[2] != '>') {
-					emit_log_char('<');
-					emit_log_char(default_message_loglevel
-						+ '0');
-					emit_log_char('>');
-					printed_len += 3;
-				}
 			}
-			log_level_unknown = 0;
+
 			if (!*p)
 				break;
 		}
+
 		emit_log_char(*p);
 		if (*p == '\n')
-			log_level_unknown = 1;
+			new_text_line = 1;
 	}
 
 	/*

Re: [PATCH 1/2] printk: Refactor processing of line severity tokens

[Ingo Molnar]

* Nick Andrew <nick@nick-andrew.net> wrote:

> printk: Refactor processing of line severity tokens
> 
> Restructure the logic of vprintk() so the processing of the leading 3 
> characters of each input line is in one place, regardless whether 
> printk_time is enabled. This makes the code smaller and easier to 
> understand.

thanks, applied - nice cleanup!

i also added the size stats:

   text    data     bss     dec     hex filename
   6157     397 1049804 1056358  101e66 printk.o.before
   6117     397 1049804 1056318  101e3e printk.o.after

	Ingo

[PATCH 2/2] printk: Remember the message level for multi-line output

[Nick Andrew]

printk: Remember the message level for multi-line output

printk(KERN_ALERT "Danger Will Robinson!\nAlien Approaching!\n");

At present this will result in one message at ALERT level and one
at the current default message loglevel (e.g. WARNING). This is
non-intuitive.

Modify vprintk() to remember the message loglevel each time it
is specified and use it for subsequent lines of output which do
not specify one, within the same call to printk.

Signed-off-by: Nick Andrew <nick@nick-andrew.net>
---
This is the third revision.

 kernel/printk.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)


diff --git a/kernel/printk.c b/kernel/printk.c
index 02ca845..5c97eb1 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -660,6 +660,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	static char printk_buf[1024];
 
 	int printed_len = 0;
+	int current_log_level = default_message_loglevel;
 	unsigned long flags;
 	int this_cpu;
 	char *p;
@@ -709,7 +710,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
 	 */
 	for (p = printk_buf; *p; p++) {
 		if (new_text_line) {
-			int current_log_level = default_message_loglevel;
 			/* If a token, set current_log_level and skip over */
 			if (p[0] == '<' && p[1] >= '0' && p[1] <= '7' &&
 			    p[2] == '>') {

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Ingo Molnar]

* Nick Andrew <nick@nick-andrew.net> wrote:

> printk: Remember the message level for multi-line output
> 
> printk(KERN_ALERT "Danger Will Robinson!\nAlien Approaching!\n");
> 
> At present this will result in one message at ALERT level and one at 
> the current default message loglevel (e.g. WARNING). This is 
> non-intuitive.
> 
> Modify vprintk() to remember the message loglevel each time it is 
> specified and use it for subsequent lines of output which do not 
> specify one, within the same call to printk.

i've applied this too for testing.

but multi-line strings are a bit unclean i think: each message line 
should have its separate printk.

will your patch leave the behavior of multiple calls to printk alone? 
I.e. if i do:

  printk(KERN_ALERT "Danger Will Robinson!\n");
  printk("Alien Approaching!\n");

then we'll still get a KERN_ALERT plus a default printk, right? In that 
case my earlier observation about this patch is moot and i guess it's 
fine to do this.

	Ingo

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Nick Andrew]

On Mon, Apr 14, 2008 at 10:03:51AM +0200, Ingo Molnar wrote:
> 
> * Nick Andrew <nick@nick-andrew.net> wrote:
> 
> > printk: Remember the message level for multi-line output
> > 
> > printk(KERN_ALERT "Danger Will Robinson!\nAlien Approaching!\n");
> > 
> > At present this will result in one message at ALERT level and one at 
> > the current default message loglevel (e.g. WARNING). This is 
> > non-intuitive.
> > 
> > Modify vprintk() to remember the message loglevel each time it is 
> > specified and use it for subsequent lines of output which do not 
> > specify one, within the same call to printk.
> 
> i've applied this too for testing.
> 
> but multi-line strings are a bit unclean i think: each message line 
> should have its separate printk.

You'd think. But there are a lot of calls to printk() with multi-line
format strings; developers clearly expect it to "just work" and
that a message level set at the start will be retained across lines.

> will your patch leave the behavior of multiple calls to printk alone? 
> I.e. if i do:
> 
>   printk(KERN_ALERT "Danger Will Robinson!\n");
>   printk("Alien Approaching!\n");
> 
> then we'll still get a KERN_ALERT plus a default printk, right?

Yes, quite. The state of whether we're inside a line is retained
across calls to printk (from anywhere in the system) - this allows
code like this to usually do what you expect:

	printk(KERN_ERR "Error:");
	for (i = 0; i < 16; ++i) {
		printk("  %02x", i);
	}
	printk("\n");

But in your example the first printk call contains a \n at the
end of the line and so upon entry to the second printk call
the function knows a new line is beginning.

The message level is a local variable. It's set to the default
at function entry, and is recalculated at the beginning of each
new line. It's changed only if a new line begins with a token.
So subsequent new lines which don't contain a token reuse the
previous value ... only within a single call to printk().

Nick.
-- 
PGP Key ID = 0x418487E7                      http://www.nick-andrew.net/
PGP Key fingerprint = B3ED 6894 8E49 1770 C24A  67E3 6266 6EB9 4184 87E7

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Ingo Molnar]

* Nick Andrew <nick@nick-andrew.net> wrote:

> > i've applied this too for testing.
> > 
> > but multi-line strings are a bit unclean i think: each message line 
> > should have its separate printk.
> 
> You'd think. But there are a lot of calls to printk() with multi-line 
> format strings; developers clearly expect it to "just work" and that a 
> message level set at the start will be retained across lines.

ok :-)

> > will your patch leave the behavior of multiple calls to printk alone? 
> > I.e. if i do:
> > 
> >   printk(KERN_ALERT "Danger Will Robinson!\n");
> >   printk("Alien Approaching!\n");
> > 
> > then we'll still get a KERN_ALERT plus a default printk, right?
> 
> Yes, quite. The state of whether we're inside a line is retained 
> across calls to printk (from anywhere in the system) - this allows 
> code like this to usually do what you expect:
> 
> 	printk(KERN_ERR "Error:");
> 	for (i = 0; i < 16; ++i) {
> 		printk("  %02x", i);
> 	}
> 	printk("\n");
> 
> But in your example the first printk call contains a \n at the end of 
> the line and so upon entry to the second printk call the function 
> knows a new line is beginning.

ok - i think your change is a good one.

btw., we could also start emitting debug warnings that the printk is not 
conform. Something like:

  "INFO: the previous printk was done without a KERN_ annotation"

?

	Ingo

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Nick Andrew]

On Mon, Apr 14, 2008 at 12:26:34PM +0200, Ingo Molnar wrote:
> * Nick Andrew <nick@nick-andrew.net> wrote:
> > Yes, quite. The state of whether we're inside a line is retained 
> > across calls to printk (from anywhere in the system) - this allows 
> > code like this to usually do what you expect:
> > 
> > 	printk(KERN_ERR "Error:");
> > 	for (i = 0; i < 16; ++i) {
> > 		printk("  %02x", i);
> > 	}
> > 	printk("\n");
> > 
> > But in your example the first printk call contains a \n at the end of 
> > the line and so upon entry to the second printk call the function 
> > knows a new line is beginning.
> 
> ok - i think your change is a good one.

Thank you.

> btw., we could also start emitting debug warnings that the printk is not 
> conform. Something like:
> 
>   "INFO: the previous printk was done without a KERN_ annotation"

There are 20k+ instances of this in the codebase; we don't need a
runtime message to find them. If you annotate them all, that will
add up to 60k to the binary size. Perhaps it's best to retain the
default support.

Nick.
-- 
PGP Key ID = 0x418487E7                      http://www.nick-andrew.net/
PGP Key fingerprint = B3ED 6894 8E49 1770 C24A  67E3 6266 6EB9 4184 87E7

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Johannes Weiner]

Hi Ingo,

Ingo Molnar <mingo@elte.hu> writes:

> btw., we could also start emitting debug warnings that the printk is not 
> conform. Something like:
>
>   "INFO: the previous printk was done without a KERN_ annotation"

Urgh, that would become very noisy.  If, at all, I'd suggest a config
option like CONFIG_DEBUG_PRINTK_USAGE and then add a prefix string to
each printk()ed line missing a severity level.

printk("foo\n");
=> "[FIX PRINTK] foo"

	Hannes

Re: [PATCH 2/2] printk: Remember the message level for multi-line output

[Ingo Molnar]

* Johannes Weiner <hannes@saeurebad.de> wrote:

> Hi Ingo,
> 
> Ingo Molnar <mingo@elte.hu> writes:
> 
> > btw., we could also start emitting debug warnings that the printk is not 
> > conform. Something like:
> >
> >   "INFO: the previous printk was done without a KERN_ annotation"
> 
> Urgh, that would become very noisy.  If, at all, I'd suggest a config
> option like CONFIG_DEBUG_PRINTK_USAGE and then add a prefix string to
> each printk()ed line missing a severity level.
> 
> printk("foo\n");
> => "[FIX PRINTK] foo"

yes, of course hidden behind a non-default Kconfig variable, like we do 
it with most debug helpers.

	Ingo