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

[PATCH] 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.

Restructure the logic so the processing of the leading 3 characters
of each input line is in one place, regardless whether printk_time
is enabled.

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

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


diff --git a/kernel/printk.c b/kernel/printk.c
index 6bc98f9..371a00a 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,53 @@ 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;
+			}
+
+			/* 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] printk: Remember the message level for multi-line output

[Nick Andrew]

On Sun, Apr 13, 2008 at 02:18:54AM +1000, Nick Andrew wrote:
> -	static int log_level_unknown = 1;
> +	static int new_text_line = 1;

Further to the previous patch, maintaining the state of being in the
middle of an output line across calls to printk() opens up the
possibility of log corruption when calling code uses printk() to
output fragments of a line. This seems to happen a lot in the
codebase, for example (from arch/blackfin/kernel/traps.c):

        printk(KERN_NOTICE "Stack from %08lx:", (unsigned long)stack);
        for (i = 0; i < kstack_depth_to_print; i++) {
                if (stack + 1 > endstack)
                        break;
                if (i % 8 == 0)
                        printk("\n" KERN_NOTICE "       ");
                printk(" %08lx", *stack++);
        }
        printk("\n");

The caller should be building complete output lines, at a minimum.
Or, to maintain the convenient coding, there would need to be an
intermediate function which buffers the partial lines until the
caller issues a flush call.

Nick.

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

[Ingo Molnar]

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

> 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.
> 
> Restructure the logic so the processing of the leading 3 characters of 
> each input line is in one place, regardless whether printk_time is 
> enabled.

hm, i'm not sure about the change itself (printks are often random, so 
the output to the console would depend on printk ordering), but the 
combined effect seems to be a nice cleanup that reduces the linecount:

>  1 files changed, 27 insertions(+), 34 deletions(-)

so how about splitting it into two, first the code restructuring then a 
small add-on that does your feature? Does this make sense to you? This 
way, even if the feature ends up not being applied, we'll have your nice 
cleanup :-)

	Ingo

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

[Nick Andrew]

On Sun, Apr 13, 2008 at 09:40:07AM +0200, Ingo Molnar wrote:
> > Restructure the logic so the processing of the leading 3 characters of 
> > each input line is in one place, regardless whether printk_time is 
> > enabled.
> 
> hm, i'm not sure about the change itself (printks are often random, so 
> the output to the console would depend on printk ordering), but the 
> combined effect seems to be a nice cleanup that reduces the linecount:

As I understand the code, if a single call to printk() includes multiple
lines of text then those lines will be contiguous in the console output.

So if one thread does printk(KERN_ERR "aaaaa\nbbbbb\n") and another
does printk(KERN_ERR "ccccc\n") then it's not possible for the buffer
to contain "<3>aaaaa\n<3>ccccc\n<3>bbbbb\n".

On the other hand, multiple calls to printk won't necessarily have
contiguous output. This affects code like arch/blackfin/kernel/traps.c
as I described in another thread which behaves like it's the only one
doing printk().

> >  1 files changed, 27 insertions(+), 34 deletions(-)
> 
> so how about splitting it into two, first the code restructuring then a 
> small add-on that does your feature? Does this make sense to you? This 
> way, even if the feature ends up not being applied, we'll have your nice 
> cleanup :-)

Can do.

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] printk: Remember the message level for multi-line output

[Nick Andrew]

On Sun, Apr 13, 2008 at 09:34:53PM +1000, Nick Andrew wrote:
> On Sun, Apr 13, 2008 at 09:40:07AM +0200, Ingo Molnar wrote:
> > so how about splitting it into two, first the code restructuring then a 
> > small add-on that does your feature? Does this make sense to you? This 
> > way, even if the feature ends up not being applied, we'll have your nice 
> > cleanup :-)
> 
> Can do.

lkml: I posted a 2-part patch and forgot to set the References, so it's in a
new thread now.

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