[PATCH] printk: flush conflicting continuation line

[PATCH] printk: flush conflicting continuation line

[Arun KS]

[-- Attachment #1: Type: text/plain, Size: 1460 bytes --]

>From d751f9a0cb6329ae3171f6e1cb85e4a3aa792d73 Mon Sep 17 00:00:00 2001
From: Arun KS <arun.ks@broadcom.com>
Date: Wed, 1 Jan 2014 17:24:46 +0530
Subject: printk: flush conflicting continuation line

An earlier newline was missing and current print is from different task.
In this scenario flush the continuation line and store this line seperatly.

This patch fix the below scenario of timestamp interleaving,
<6>[   28.154370 ] read_word_reg : reg[0x 3], reg[0x 4]  data [0x 642]
<6>[   28.155428 ] uart disconnect
<6>[   31.947341 ] dvfs[cpufreq.c<275>]:plug-in cpu<1> done
<4>[   28.155445 ] UART detached : send switch state 201
<6>[   32.014112 ] read_reg : reg[0x 3] data[0x21]

Signed-off-by: Arun KS <getarunks@gmail.com>
Signed-off-by: Arun KS <arun.ks@broadcom.com>
---
 kernel/printk/printk.c |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index be7c86b..65ccaeb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1604,7 +1604,10 @@ asmlinkage int vprintk_emit(int facility, int level,
  if (!(lflags & LOG_PREFIX))
  stored = cont_add(facility, level, text, text_len);
  cont_flush(LOG_NEWLINE);
- }
+ /* Flush conflicting buffer. An earlier newline was missing
+ * and current print is from different task */
+ } else if (cont.len && cont.owner != current)
+ cont_flush(LOG_NEWLINE);

  if (!stored)
  log_store(facility, level, lflags, 0,
-- 
1.7.6

[-- Attachment #2: 0001-printk-flush-conflicting-continuation-line.patch --]
[-- Type: application/octet-stream, Size: 1477 bytes --]

From d751f9a0cb6329ae3171f6e1cb85e4a3aa792d73 Mon Sep 17 00:00:00 2001
From: Arun KS <arun.ks@broadcom.com>
Date: Wed, 1 Jan 2014 17:24:46 +0530
Subject: printk: flush conflicting continuation line

An earlier newline was missing and current print is from different task.
In this scenario flush the continuation line and store this line seperatly.

This patch fix the below scenario of timestamp interleaving,
<6>[   28.154370 ] read_word_reg : reg[0x 3], reg[0x 4]  data [0x 642]
<6>[   28.155428 ] uart disconnect
<6>[   31.947341 ] dvfs[cpufreq.c<275>]:plug-in cpu<1> done
<4>[   28.155445 ] UART detached : send switch state 201
<6>[   32.014112 ] read_reg : reg[0x 3] data[0x21]

Signed-off-by: Arun KS <getarunks@gmail.com>
Signed-off-by: Arun KS <arun.ks@broadcom.com>
---
 kernel/printk/printk.c |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index be7c86b..65ccaeb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1604,7 +1604,10 @@ asmlinkage int vprintk_emit(int facility, int level,
 			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text, text_len);
 			cont_flush(LOG_NEWLINE);
-		}
+		/* Flush conflicting buffer. An earlier newline was missing
+		* and current print is from different task */
+		} else if (cont.len && cont.owner != current)
+			cont_flush(LOG_NEWLINE);
 
 		if (!stored)
 			log_store(facility, level, lflags, 0,
-- 
1.7.6

Re: [PATCH] printk: flush conflicting continuation line

[Andrew Morton]

On Wed, 1 Jan 2014 17:44:06 +0530 Arun KS <arunks.linux@gmail.com> wrote:

> >From d751f9a0cb6329ae3171f6e1cb85e4a3aa792d73 Mon Sep 17 00:00:00 2001
> From: Arun KS <arun.ks@broadcom.com>
> Date: Wed, 1 Jan 2014 17:24:46 +0530
> Subject: printk: flush conflicting continuation line
> 
> An earlier newline was missing and current print is from different task.
> In this scenario flush the continuation line and store this line seperatly.
> 
> This patch fix the below scenario of timestamp interleaving,
> <6>[   28.154370 ] read_word_reg : reg[0x 3], reg[0x 4]  data [0x 642]
> <6>[   28.155428 ] uart disconnect
> <6>[   31.947341 ] dvfs[cpufreq.c<275>]:plug-in cpu<1> done
> <4>[   28.155445 ] UART detached : send switch state 201
> <6>[   32.014112 ] read_reg : reg[0x 3] data[0x21]
> 
> ...
>
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1604,7 +1604,10 @@ asmlinkage int vprintk_emit(int facility, int level,
>   if (!(lflags & LOG_PREFIX))
>   stored = cont_add(facility, level, text, text_len);
>   cont_flush(LOG_NEWLINE);
> - }
> + /* Flush conflicting buffer. An earlier newline was missing
> + * and current print is from different task */
> + } else if (cont.len && cont.owner != current)
> + cont_flush(LOG_NEWLINE);
> 
>   if (!stored)
>   log_store(facility, level, lflags, 0,

Your email client makes a horrid mess of the patches :(

I *think* it's right.  But the code can be significantly simplified and
optimised.  Please review:

	} else {
		bool stored = false;

		/*
		 * If an earlier newline was missing and it was the same task,
		 * either merge it with the current buffer and flush, or if
		 * there was a race with interrupts (prefix == true) then just
		 * flush it out and store this line separately.
		 * If the preceding printk was from a different task and missed
		 * a newline, flush and append the newline.
		 */
		if (cont.len) {
			if (cont.owner == current && !(lflags & LOG_PREFIX))
				stored = cont_add(facility, level, text,
						  text_len);
			cont_flush(LOG_NEWLINE);
		}

		if (!stored)
			log_store(facility, level, lflags, 0,
				  dict, dictlen, text, text_len);
	}



--- a/kernel/printk/printk.c~printk-flush-conflicting-continuation-line-fix
+++ a/kernel/printk/printk.c
@@ -1595,15 +1595,15 @@ asmlinkage int vprintk_emit(int facility
 		 * either merge it with the current buffer and flush, or if
 		 * there was a race with interrupts (prefix == true) then just
 		 * flush it out and store this line separately.
+		 * If the preceding printk was from a different task and missed
+		 * a newline, flush and append the newline.
 		 */
-		if (cont.len && cont.owner == current) {
-			if (!(lflags & LOG_PREFIX))
-				stored = cont_add(facility, level, text, text_len);
-			cont_flush(LOG_NEWLINE);
-		/* Flush conflicting buffer. An earlier newline was missing
-		* and current print is from different task */
-		} else if (cont.len && cont.owner != current)
+		if (cont.len) {
+			if (cont.owner == current && !(lflags & LOG_PREFIX))
+				stored = cont_add(facility, level, text,
+						  text_len);
 			cont_flush(LOG_NEWLINE);
+		}
 
 		if (!stored)
 			log_store(facility, level, lflags, 0,
_

Re: [PATCH] printk: flush conflicting continuation line

[Joe Perches]

(Adding Kay to cc's)

Kay?  any opinion on correctness?

On Thu, 2014-01-02 at 14:55 -0800, Andrew Morton wrote:
> On Wed, 1 Jan 2014 17:44:06 +0530 Arun KS <arunks.linux@gmail.com> wrote:
> 
> > >From d751f9a0cb6329ae3171f6e1cb85e4a3aa792d73 Mon Sep 17 00:00:00 2001
> > From: Arun KS <arun.ks@broadcom.com>
> > Date: Wed, 1 Jan 2014 17:24:46 +0530
> > Subject: printk: flush conflicting continuation line
> > 
> > An earlier newline was missing and current print is from different task.
> > In this scenario flush the continuation line and store this line seperatly.
> > 
> > This patch fix the below scenario of timestamp interleaving,
> > <6>[   28.154370 ] read_word_reg : reg[0x 3], reg[0x 4]  data [0x 642]
> > <6>[   28.155428 ] uart disconnect
> > <6>[   31.947341 ] dvfs[cpufreq.c<275>]:plug-in cpu<1> done
> > <4>[   28.155445 ] UART detached : send switch state 201
> > <6>[   32.014112 ] read_reg : reg[0x 3] data[0x21]
> > 
> > ...
> >
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1604,7 +1604,10 @@ asmlinkage int vprintk_emit(int facility, int level,
> >   if (!(lflags & LOG_PREFIX))
> >   stored = cont_add(facility, level, text, text_len);
> >   cont_flush(LOG_NEWLINE);
> > - }
> > + /* Flush conflicting buffer. An earlier newline was missing
> > + * and current print is from different task */
> > + } else if (cont.len && cont.owner != current)
> > + cont_flush(LOG_NEWLINE);
> > 
> >   if (!stored)
> >   log_store(facility, level, lflags, 0,
> 
> Your email client makes a horrid mess of the patches :(
> 
> I *think* it's right.  But the code can be significantly simplified and
> optimised.  Please review:
> 
> 	} else {
> 		bool stored = false;
> 
> 		/*
> 		 * If an earlier newline was missing and it was the same task,
> 		 * either merge it with the current buffer and flush, or if
> 		 * there was a race with interrupts (prefix == true) then just
> 		 * flush it out and store this line separately.
> 		 * If the preceding printk was from a different task and missed
> 		 * a newline, flush and append the newline.
> 		 */
> 		if (cont.len) {
> 			if (cont.owner == current && !(lflags & LOG_PREFIX))
> 				stored = cont_add(facility, level, text,
> 						  text_len);
> 			cont_flush(LOG_NEWLINE);
> 		}
> 
> 		if (!stored)
> 			log_store(facility, level, lflags, 0,
> 				  dict, dictlen, text, text_len);
> 	}
> 
> 
> 
> --- a/kernel/printk/printk.c~printk-flush-conflicting-continuation-line-fix
> +++ a/kernel/printk/printk.c
> @@ -1595,15 +1595,15 @@ asmlinkage int vprintk_emit(int facility
>  		 * either merge it with the current buffer and flush, or if
>  		 * there was a race with interrupts (prefix == true) then just
>  		 * flush it out and store this line separately.
> +		 * If the preceding printk was from a different task and missed
> +		 * a newline, flush and append the newline.
>  		 */
> -		if (cont.len && cont.owner == current) {
> -			if (!(lflags & LOG_PREFIX))
> -				stored = cont_add(facility, level, text, text_len);
> -			cont_flush(LOG_NEWLINE);
> -		/* Flush conflicting buffer. An earlier newline was missing
> -		* and current print is from different task */
> -		} else if (cont.len && cont.owner != current)
> +		if (cont.len) {
> +			if (cont.owner == current && !(lflags & LOG_PREFIX))
> +				stored = cont_add(facility, level, text,
> +						  text_len);
>  			cont_flush(LOG_NEWLINE);
> +		}
>  
>  		if (!stored)
>  			log_store(facility, level, lflags, 0,
> _

Re: [PATCH] printk: flush conflicting continuation line

[Kay Sievers]

On Fri, Jan 3, 2014 at 1:57 AM, Joe Perches <joe@perches.com> wrote:
> (Adding Kay to cc's)
>
> Kay?  any opinion on correctness?

Sounds fine by looking at it. Did not test anything though.

>> > --- a/kernel/printk/printk.c
>> > +++ b/kernel/printk/printk.c
>> > @@ -1604,7 +1604,10 @@ asmlinkage int vprintk_emit(int facility, int level,
>> >   if (!(lflags & LOG_PREFIX))
>> >   stored = cont_add(facility, level, text, text_len);
>> >   cont_flush(LOG_NEWLINE);
>> > - }
>> > + /* Flush conflicting buffer. An earlier newline was missing
>> > + * and current print is from different task */
>> > + } else if (cont.len && cont.owner != current)
>> > + cont_flush(LOG_NEWLINE);

Unless I miss something, this whole sections all go inside a:
  if (cont.len) {
    ...
    cont_flush(LOG_NEWLINE);
  }

and look a bit less confusing than the two conditions with just the
negated "current" check and duplicated flush call?

Kay