Re: [PATCH v3] printk: Have printk() never buffer its data

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

> On Mon, 2012-06-25 at 18:40 -0700, Linus Torvalds wrote:
> > On Mon, Jun 25, 2012 at 5:56 PM, Kay Sievers <kay@vrfy.org> wrote:
> > >
> > > Buffering has nice effects though:
> > > It makes continuation lines appear as one record in the buffer, not as
> > > n individual prints with n headers.
> > 
> > As I already mentioned, buffering for *logging* is different from
> > buffering for *printing*.
> > 
> > I think it might be a great idea to buffer for logging in order to
> > generate one individual buffer record there.
> > 
> > But it needs to be printed as it is generated.
> 
> That's a good idea.
> 
> Something like this could work - only minimally tested at this moment.

This breaks some powerpc configs and is in Linus' tree now as
084681d14e.

When we have printks without a newline (like show_regs()), it
sometimes:
1) drops the console output for that line (dmesg is fine).  Patch to fix
   this below.
2) adds a newline unnecessary to both console and dmesg.  I have no fix
   for this currently.
Reverting this patch fixes both problems.

Post rc4 is way to late to be adding largely untested features like
this.  

I suggest we revert this until the next merge window.

Mikey

diff --git a/kernel/printk.c b/kernel/printk.c
index dba1821..91659da 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1335,7 +1335,7 @@ static void cont_flush(void)
        if (cont.len == 0)
                return;
 
-       log_store(cont.facility, cont.level, LOG_NOCONS, cont.ts_nsec,
+       log_store(cont.facility, cont.level, LOG_DEFAULT, cont.ts_nsec,
                  NULL, 0, cont.buf, cont.len);
 
        cont.flushed = true;



> 
> 
> From: Kay Sievers <kay@vrfy.org>
> Subject: printk: flush continuation lines immediately to console
> 
> Continuation lines are buffered internally to merge the chunked
> printk()s into a single record, and to isolate potentially racy
> continuation users from usual terminated line users.
> 
> This though, has the effect that partial lines are not printed to
> the console in the moment they are emitted. In case the kernel
> crashes in the meantime, the potentially interesting printed
> information will never reach the consoles.
> 
> Here we share the continuation buffer with the console copy logic,
> and partial lines are immediately flushed to the consoles, but still
> buffered internally to improve the integrity of the messages.
> ---
> 
>  kernel/printk.c |  129 +++++++++++++++++++++++++++++++++++++++++++------------
>  1 file changed, 101 insertions(+), 28 deletions(-)
> 
> diff --git a/kernel/printk.c b/kernel/printk.c
> index a2276b9..92c34bd1 100644
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -193,12 +193,19 @@ static int console_may_schedule;
>   * separated by ',', and find the message after the ';' character.
>   */
>  
> +enum log_flags {
> +	LOG_DEFAULT = 0,
> +	LOG_NOCONS = 1,		/* already flushed, do not print to console */
> +};
> +
>  struct log {
>  	u64 ts_nsec;		/* timestamp in nanoseconds */
>  	u16 len;		/* length of entire record */
>  	u16 text_len;		/* length of text buffer */
>  	u16 dict_len;		/* length of dictionary buffer */
> -	u16 level;		/* syslog level + facility */
> +	u8 facility;		/* syslog facility */
> +	u8 flags:5;		/* internal record flags */
> +	u8 level:3;		/* syslog level */
>  };
>  
>  /*
> @@ -286,6 +293,7 @@ static u32 log_next(u32 idx)
>  
>  /* insert record into the buffer, discard old ones, update heads */
>  static void log_store(int facility, int level,
> +		      enum log_flags flags, u64 ts_nsec,
>  		      const char *dict, u16 dict_len,
>  		      const char *text, u16 text_len)
>  {
> @@ -329,8 +337,13 @@ static void log_store(int facility, int level,
>  	msg->text_len = text_len;
>  	memcpy(log_dict(msg), dict, dict_len);
>  	msg->dict_len = dict_len;
> -	msg->level = (facility << 3) | (level & 7);
> -	msg->ts_nsec = local_clock();
> +	msg->facility = facility;
> +	msg->level = level & 7;
> +	msg->flags = flags & 0x1f;
> +	if (ts_nsec > 0)
> +		msg->ts_nsec = ts_nsec;
> +	else
> +		msg->ts_nsec = local_clock();
>  	memset(log_dict(msg) + dict_len, 0, pad_len);
>  	msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
>  
> @@ -446,7 +459,7 @@ static ssize_t devkmsg_read(struct file *file, char __user *buf,
>  	ts_usec = msg->ts_nsec;
>  	do_div(ts_usec, 1000);
>  	len = sprintf(user->buf, "%u,%llu,%llu;",
> -		      msg->level, user->seq, ts_usec);
> +		      (msg->facility << 3) | msg->level, user->seq, ts_usec);
>  
>  	/* escape non-printable characters */
>  	for (i = 0; i < msg->text_len; i++) {
> @@ -787,6 +800,21 @@ static bool printk_time;
>  #endif
>  module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
>  
> +static size_t print_time(u64 ts, char *buf)
> +{
> +	unsigned long rem_nsec;
> +
> +	if (!printk_time)
> +		return 0;
> +
> +	if (!buf)
> +		return 15;
> +
> +	rem_nsec = do_div(ts, 1000000000);
> +	return sprintf(buf, "[%5lu.%06lu] ",
> +		       (unsigned long)ts, rem_nsec / 1000);
> +}
> +
>  static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
>  {
>  	size_t len = 0;
> @@ -803,18 +831,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
>  		}
>  	}
>  
> -	if (printk_time) {
> -		if (buf) {
> -			unsigned long long ts = msg->ts_nsec;
> -			unsigned long rem_nsec = do_div(ts, 1000000000);
> -
> -			len += sprintf(buf + len, "[%5lu.%06lu] ",
> -					 (unsigned long) ts, rem_nsec / 1000);
> -		} else {
> -			len += 15;
> -		}
> -	}
> -
> +	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
>  	return len;
>  }
>  
> @@ -1272,15 +1289,25 @@ static inline void printk_delay(void)
>  	}
>  }
>  
> +/*
> + * Continuation lines are buffered, and not committed to the record buffer
> + * until the line is complete, or a race forces a flush. The line fragments
> + * though, are printed immediately to the consoles to ensure everything has
> + * reached the console in case of a kernel crash.
> + */
> +static char cont_buf[LOG_LINE_MAX];
> +static size_t cont_len;
> +static size_t cont_cons;
> +static size_t cont_cons_len;
> +static int cont_level;
> +static u64 cont_ts_nsec;
> +static struct task_struct *cont_task;
> +
>  asmlinkage int vprintk_emit(int facility, int level,
>  			    const char *dict, size_t dictlen,
>  			    const char *fmt, va_list args)
>  {
>  	static int recursion_bug;
> -	static char cont_buf[LOG_LINE_MAX];
> -	static size_t cont_len;
> -	static int cont_level;
> -	static struct task_struct *cont_task;
>  	static char textbuf[LOG_LINE_MAX];
>  	char *text = textbuf;
>  	size_t text_len;
> @@ -1326,7 +1353,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		recursion_bug = 0;
>  		printed_len += strlen(recursion_msg);
>  		/* emit KERN_CRIT message */
> -		log_store(0, 2, NULL, 0, recursion_msg, printed_len);
> +		log_store(0, 2, LOG_DEFAULT, 0,
> +			  NULL, 0, recursion_msg, printed_len);
>  	}
>  
>  	/*
> @@ -1369,13 +1397,17 @@ asmlinkage int vprintk_emit(int facility, int level,
>  			 * Flush earlier buffer, which is either from a
>  			 * different thread, or when we got a new prefix.
>  			 */
> -			log_store(facility, cont_level, NULL, 0, cont_buf, cont_len);
> +			log_store(facility, cont_level,
> +				  LOG_NOCONS, cont_ts_nsec,
> +				  NULL, 0, cont_buf, cont_len);
>  			cont_len = 0;
>  		}
>  
>  		if (!cont_len) {
> +			cont_cons = 0;
>  			cont_level = level;
>  			cont_task = current;
> +			cont_ts_nsec = local_clock();
>  		}
>  
>  		/* buffer or append to earlier buffer from the same thread */
> @@ -1383,6 +1415,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  			text_len = sizeof(cont_buf) - cont_len;
>  		memcpy(cont_buf + cont_len, text, text_len);
>  		cont_len += text_len;
> +		cont_cons_len = cont_len;
> +		printed_len = text_len;
>  	} else {
>  		if (cont_len && cont_task == current) {
>  			if (prefix) {
> @@ -1392,6 +1426,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  				 * with an interrupt.
>  				 */
>  				log_store(facility, cont_level,
> +					  LOG_NOCONS, cont_ts_nsec,
>  					  NULL, 0, cont_buf, cont_len);
>  				cont_len = 0;
>  			}
> @@ -1401,14 +1436,15 @@ asmlinkage int vprintk_emit(int facility, int level,
>  				text_len = sizeof(cont_buf) - cont_len;
>  			memcpy(cont_buf + cont_len, text, text_len);
>  			cont_len += text_len;
> +			cont_cons_len = cont_len;
>  			log_store(facility, cont_level,
> +				  LOG_NOCONS, cont_ts_nsec,
>  				  NULL, 0, cont_buf, cont_len);
>  			cont_len = 0;
> -			cont_task = NULL;
> -			printed_len = cont_len;
> +			printed_len = text_len;
>  		} else {
>  			/* ordinary single and terminated line */
> -			log_store(facility, level,
> +			log_store(facility, level, LOG_DEFAULT, 0,
>  				  dict, dictlen, text, text_len);
>  			printed_len = text_len;
>  		}
> @@ -1795,6 +1831,7 @@ static u32 console_idx;
>   */
>  void console_unlock(void)
>  {
> +	static char text[LOG_LINE_MAX];
>  	static u64 seen_seq;
>  	unsigned long flags;
>  	bool wake_klogd = false;
> @@ -1807,10 +1844,37 @@ void console_unlock(void)
>  
>  	console_may_schedule = 0;
>  
> +	/* flush buffered message fragment immediately to console */
> +	raw_spin_lock_irqsave(&logbuf_lock, flags);
> +	if (cont_cons_len && (cont_cons < cont_cons_len || !cont_len)) {
> +		size_t textlen = 0;
> +		size_t len;
> +
> +		len = cont_cons_len - cont_cons;
> +		if (!cont_cons)
> +			textlen = print_time(cont_ts_nsec, text);
> +		memcpy(text + textlen, cont_buf + cont_cons, len);
> +		textlen += len;
> +		cont_cons = cont_cons_len;
> +
> +		if (!cont_len) {
> +			/* last chunk of line; terminate */
> +			text[textlen++] = '\n';
> +			cont_cons_len = 0;
> +		}
> +		raw_spin_unlock(&logbuf_lock);
> +
> +		stop_critical_timings();
> +		call_console_drivers(cont_level, text, textlen);
> +		start_critical_timings();
> +
> +		local_irq_restore(flags);
> +	} else
> +		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
> +
>  again:
>  	for (;;) {
>  		struct log *msg;
> -		static char text[LOG_LINE_MAX];
>  		size_t len;
>  		int level;
>  
> @@ -1825,13 +1889,22 @@ again:
>  			console_seq = log_first_seq;
>  			console_idx = log_first_idx;
>  		}
> -
> +skip:
>  		if (console_seq == log_next_seq)
>  			break;
>  
>  		msg = log_from_idx(console_idx);
> -		level = msg->level & 7;
> +		if (msg->flags & LOG_NOCONS) {
> +			/*
> +			 * Skip record we have buffered and already printed
> +			 * directly to the console when we received it.
> +			 */
> +			console_idx = log_next(console_idx);
> +			console_seq++;
> +			goto skip;
> +		}
>  
> +		level = msg->level;
>  		len = msg_print_text(msg, false, text, sizeof(text));
>  
>  		console_idx = log_next(console_idx);
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Thu, Jul 5, 2012 at 9:03 AM, Michael Neuling <mikey@neuling.org> wrote:
>> On Mon, 2012-06-25 at 18:40 -0700, Linus Torvalds wrote:

>> > I think it might be a great idea to buffer for logging in order to
>> > generate one individual buffer record there.
>> >
>> > But it needs to be printed as it is generated.
>>
>> That's a good idea.
>>
>> Something like this could work - only minimally tested at this moment.
>
> This breaks some powerpc configs and is in Linus' tree now as
> 084681d14e.
>
> When we have printks without a newline (like show_regs()), it
> sometimes:

x86 has that a lot too.

> 1) drops the console output for that line (dmesg is fine).  Patch to fix
>    this below.

That doesn't look right. We should already have put that out to the
console, and we only want to store it away. Your patch, as expected,
duplicates all the continuation lines on the console here:
[    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0

> 2) adds a newline unnecessary to both console and dmesg.  I have no fix
>    for this currently.
> Reverting this patch fixes both problems.

Not here. I can't reproduce any of this here, it all looks fine.

Is that possibly some early printk() or other console trickery on ppc
that produces the issue?

Thanks,
Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Thu, Jul 5, 2012 at 10:39 AM, Kay Sievers <kay@vrfy.org> wrote:
> On Thu, Jul 5, 2012 at 9:03 AM, Michael Neuling <mikey@neuling.org> wrote:
>>> On Mon, 2012-06-25 at 18:40 -0700, Linus Torvalds wrote:
>
>>> > I think it might be a great idea to buffer for logging in order to
>>> > generate one individual buffer record there.
>>> >
>>> > But it needs to be printed as it is generated.
>>>
>>> That's a good idea.
>>>
>>> Something like this could work - only minimally tested at this moment.
>>
>> This breaks some powerpc configs and is in Linus' tree now as
>> 084681d14e.
>>
>> When we have printks without a newline (like show_regs()), it
>> sometimes:
>
> x86 has that a lot too.
>
>> 1) drops the console output for that line (dmesg is fine).  Patch to fix
>>    this below.
>
> That doesn't look right. We should already have put that out to the
> console, and we only want to store it away. Your patch, as expected,
> duplicates all the continuation lines on the console here:
> [    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
> [    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
>
>> 2) adds a newline unnecessary to both console and dmesg.  I have no fix
>>    for this currently.
>> Reverting this patch fixes both problems.
>
> Not here. I can't reproduce any of this here, it all looks fine.
>
> Is that possibly some early printk() or other console trickery on ppc
> that produces the issue?

Or, are you really sure this isn't just a race with another printk and
the content got merged with some other line of the output? The added
newline you mention could suggest that.

With the buffering for the console output removed, I see garbled
console output here too (like we always had before the new kmsg) when
continuation printks race against printks from any other process. That
was all gone with the buffering (only two continuation prints would
race, not any other), but we needed to skip buffering the console
output for other, more important reasons.

Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Kay Sievers <kay@vrfy.org> wrote:

> On Thu, Jul 5, 2012 at 10:39 AM, Kay Sievers <kay@vrfy.org> wrote:
> > On Thu, Jul 5, 2012 at 9:03 AM, Michael Neuling <mikey@neuling.org> wrote:
> >>> On Mon, 2012-06-25 at 18:40 -0700, Linus Torvalds wrote:
> >
> >>> > I think it might be a great idea to buffer for logging in order to
> >>> > generate one individual buffer record there.
> >>> >
> >>> > But it needs to be printed as it is generated.
> >>>
> >>> That's a good idea.
> >>>
> >>> Something like this could work - only minimally tested at this moment.
> >>
> >> This breaks some powerpc configs and is in Linus' tree now as
> >> 084681d14e.
> >>
> >> When we have printks without a newline (like show_regs()), it
> >> sometimes:
> >
> > x86 has that a lot too.
> >
> >> 1) drops the console output for that line (dmesg is fine).  Patch to fix
> >>    this below.
> >
> > That doesn't look right. We should already have put that out to the
> > console, and we only want to store it away. Your patch, as expected,
> > duplicates all the continuation lines on the console here:
> > [    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
> > [    0.674957] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
> >
> >> 2) adds a newline unnecessary to both console and dmesg.  I have no fix
> >>    for this currently.
> >> Reverting this patch fixes both problems.
> >
> > Not here. I can't reproduce any of this here, it all looks fine.
> >
> > Is that possibly some early printk() or other console trickery on ppc
> > that produces the issue?
> 
> Or, are you really sure this isn't just a race with another printk and
> the content got merged with some other line of the output? The added
> newline you mention could suggest that.

I can make 1) happen on UP or SMP.

I can only make 2) happen on SMP.  It's when the second CPU is coming up
and it's printing something.  The first CPU isn't printing anything at
this stage (there is no garbled console here) so I don't think it's a
race.  I see it consistently in show_regs().  Every printk without a
newline.  ie I get this:
---
NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc5-mikey)
MSR: 9000000000021032 
<
SF
,HV
,ME
,IR
,DR
,RI
>
  CR: 28000042  XER: 22000000
SOFTE: 0
CFAR: c0000000007402f8
TASK = c00000007e56bb40[0] 'swapper/1' THREAD: c00000007e59c000
 CPU: 1
---

It's consistent for printks without newlines in show_regs().  MSR
through to XER should all be on the same line.

Mikey

> With the buffering for the console output removed, I see garbled
> console output here too (like we always had before the new kmsg) when
> continuation printks race against printks from any other process. That
> was all gone with the buffering (only two continuation prints would
> race, not any other), but we needed to skip buffering the console
> output for other, more important reasons.

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Thu, Jul 5, 2012 at 12:20 PM, Michael Neuling <mikey@neuling.org> wrote:

> I can only make 2) happen on SMP.  It's when the second CPU is coming up
> and it's printing something.  The first CPU isn't printing anything at
> this stage (there is no garbled console here) so I don't think it's a
> race.  I see it consistently in show_regs().  Every printk without a
> newline.  ie I get this:
> ---
> NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc5-mikey)
> MSR: 9000000000021032
> <
> SF
> ,HV
> ,ME
> ,IR
> ,DR
> ,RI
>>
>   CR: 28000042  XER: 22000000
> SOFTE: 0
> CFAR: c0000000007402f8
> TASK = c00000007e56bb40[0] 'swapper/1' THREAD: c00000007e59c000
>  CPU: 1
> ---
>
> It's consistent for printks without newlines in show_regs().  MSR
> through to XER should all be on the same line.

I see. Something to fix then, I'll have a look.

Does this happen only very early during bootup, or also later when the
box fully initialized?

The output of 'dmesg' later looks always correct, right?

Thanks,
Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Thu, 2012-07-05 at 13:47 +0200, Kay Sievers wrote:
> On Thu, Jul 5, 2012 at 12:20 PM, Michael Neuling <mikey@neuling.org> wrote:
> 
> > I can only make 2) happen on SMP.  It's when the second CPU is coming up
> > and it's printing something.  The first CPU isn't printing anything at
> > this stage (there is no garbled console here) so I don't think it's a
> > race.  I see it consistently in show_regs().  Every printk without a
> > newline.  ie I get this:
> > ---
> > NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> > REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc5-mikey)
> > MSR: 9000000000021032
> > <
> > SF
> > ,HV
> > ,ME
> > ,IR
> > ,DR
> > ,RI
> >>
> >   CR: 28000042  XER: 22000000
> > SOFTE: 0
> > CFAR: c0000000007402f8
> > TASK = c00000007e56bb40[0] 'swapper/1' THREAD: c00000007e59c000
> >  CPU: 1
> > ---
> >
> > It's consistent for printks without newlines in show_regs().  MSR
> > through to XER should all be on the same line.
> 
> I see. Something to fix then, I'll have a look.
> 
> Does this happen only very early during bootup, or also later when the
> box fully initialized?
> 
> The output of 'dmesg' later looks always correct, right?

If it's an early printk issue like it looks like, where stuff got
printed before we had any console registered, this might fix the issue
you are seeing.

Could you possibly try this patch?

Thanks,
Kay


--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -1957,6 +1951,12 @@ skip:
 			 */
 			console_idx = log_next(console_idx);
 			console_seq++;
+			/*
+			 * We will get here again when we register a new
+			 * CON_PRINTBUFFER console. Clear the flag so we
+			 * will properly dump everything later.
+			 */
+			msg->flags &= ~LOG_NOCONS;
 			goto skip;
 		}
 

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Kay Sievers <kay@vrfy.org> wrote:

> On Thu, 2012-07-05 at 13:47 +0200, Kay Sievers wrote:
> > On Thu, Jul 5, 2012 at 12:20 PM, Michael Neuling <mikey@neuling.org> wrote:
> > 
> > > I can only make 2) happen on SMP.  It's when the second CPU is coming up
> > > and it's printing something.  The first CPU isn't printing anything at
> > > this stage (there is no garbled console here) so I don't think it's a
> > > race.  I see it consistently in show_regs().  Every printk without a
> > > newline.  ie I get this:
> > > ---
> > > NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> > > REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc5-mikey)
> > > MSR: 9000000000021032
> > > <
> > > SF
> > > ,HV
> > > ,ME
> > > ,IR
> > > ,DR
> > > ,RI
> > >>
> > >   CR: 28000042  XER: 22000000
> > > SOFTE: 0
> > > CFAR: c0000000007402f8
> > > TASK = c00000007e56bb40[0] 'swapper/1' THREAD: c00000007e59c000
> > >  CPU: 1
> > > ---
> > >
> > > It's consistent for printks without newlines in show_regs().  MSR
> > > through to XER should all be on the same line.
> > 
> > I see. Something to fix then, I'll have a look.
> > 
> > Does this happen only very early during bootup, or also later when the
> > box fully initialized?

I'm seeing during boot but not later (xmon (ppc kernel debugger) doesn't
see it if I do 'echo x > /proc/sysrq-trigger') .  I wouldn't say
it's "very early boot".  It's a secondary CPU coming up and the primary
is waiting for it.  We've already configured the console when this
happens.

> > 
> > The output of 'dmesg' later looks always correct, right?

No, dmesg also has the extra new lines: eg

<4>NIP: c00000000004e234 LR: c00000000004e230 CTR: 0000000000000000
<4>REGS: c00000007c3b7b50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
<4>MSR: 9000000000021032 
<4><
<4>SF
<4>,HV
<4>,ME
<4>,IR
<4>,DR
<4>,RI
<4>>
<4>  CR: 28000042  XER: 22000000
<4>SOFTE: 0
<4>CFAR: c0000000008139b4
<4>TASK = c00000007c3a4e00[0] 'swapper/1' THREAD: c00000007c3b4000
<4> CPU: 1
<4>

> If it's an early printk issue like it looks like, where stuff got
> printed before we had any console registered, this might fix the issue
> you are seeing.
>
> Could you possibly try this patch?

Sorry, doesn't help.  It also reprints the entire boot log to the
console once the console get inited.

FWIW HVC RTAS is the console.

Mikey

> 
> Thanks,
> Kay
> 
> 
> --- a/kernel/printk.c
> +++ b/kernel/printk.c
> @@ -1957,6 +1951,12 @@ skip:
>  			 */
>  			console_idx = log_next(console_idx);
>  			console_seq++;
> +			/*
> +			 * We will get here again when we register a new
> +			 * CON_PRINTBUFFER console. Clear the flag so we
> +			 * will properly dump everything later.
> +			 */
> +			msg->flags &= ~LOG_NOCONS;
>  			goto skip;
>  		}
>  
> 

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Fri, Jul 6, 2012 at 2:41 AM, Michael Neuling <mikey@neuling.org> wrote:

>> > Does this happen only very early during bootup, or also later when the
>> > box fully initialized?
>
> I'm seeing during boot but not later (xmon (ppc kernel debugger) doesn't
> see it if I do 'echo x > /proc/sysrq-trigger') .  I wouldn't say
> it's "very early boot".  It's a secondary CPU coming up and the primary
> is waiting for it.  We've already configured the console when this
> happens.

Sounds like an early boot console.

>> > The output of 'dmesg' later looks always correct, right?
>
> No, dmesg also has the extra new lines: eg
>
> <4>NIP: c00000000004e234 LR: c00000000004e230 CTR: 0000000000000000
> <4>REGS: c00000007c3b7b50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> <4>MSR: 9000000000021032
> <4><
> <4>SF
> <4>,HV
> <4>,ME
> <4>,IR
> <4>,DR
> <4>,RI
> <4>>
> <4>  CR: 28000042  XER: 22000000

Can you please paste the output of /dev/kmsg of this section? So we
can see the timestamps and what really went into the record buffer.

>> Could you possibly try this patch?
>
> Sorry, doesn't help.  It also reprints the entire boot log to the
> console once the console get inited.

Which is the normal behaviour to do that, right? We should not have
touched any of that logic.

Thanks,
Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Kay Sievers <kay@vrfy.org> wrote:

> On Fri, Jul 6, 2012 at 2:41 AM, Michael Neuling <mikey@neuling.org> wrote:
> 
> >> > Does this happen only very early during bootup, or also later when the
> >> > box fully initialized?
> >
> > I'm seeing during boot but not later (xmon (ppc kernel debugger) doesn't
> > see it if I do 'echo x > /proc/sysrq-trigger') .  I wouldn't say
> > it's "very early boot".  It's a secondary CPU coming up and the primary
> > is waiting for it.  We've already configured the console when this
> > happens.
> 
> Sounds like an early boot console.
> 
> >> > The output of 'dmesg' later looks always correct, right?
> >
> > No, dmesg also has the extra new lines: eg
> >
> > <4>NIP: c00000000004e234 LR: c00000000004e230 CTR: 0000000000000000
> > <4>REGS: c00000007c3b7b50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> > <4>MSR: 9000000000021032
> > <4><
> > <4>SF
> > <4>,HV
> > <4>,ME
> > <4>,IR
> > <4>,DR
> > <4>,RI
> > <4>>
> > <4>  CR: 28000042  XER: 22000000
> 
> Can you please paste the output of /dev/kmsg of this section? So we
> can see the timestamps and what really went into the record buffer.

Sure.

4,89,24561;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
4,90,24576;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
4,91,24583;MSR: 9000000000021032 
4,92,24586;<
4,93,24591;SF
4,94,24596;,HV
4,95,24601;,ME
4,96,24606;,IR
4,97,24611;,DR
4,98,24616;,RI
4,99,24619;>
4,100,24628;  CR: 28000042  XER: 22000000

> 
> >> Could you possibly try this patch?
> >
> > Sorry, doesn't help.  It also reprints the entire boot log to the
> > console once the console get inited.
> 
> Which is the normal behaviour to do that, right? We should not have
> touched any of that logic.

Not until this patch you asked me to try.  Hence why I noted it.  

Mikey

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Michael Neuling <mikey@neuling.org> wrote:

> Kay Sievers <kay@vrfy.org> wrote:
> 
> > On Fri, Jul 6, 2012 at 2:41 AM, Michael Neuling <mikey@neuling.org> wrote:
> > 
> > >> > Does this happen only very early during bootup, or also later when the
> > >> > box fully initialized?
> > >
> > > I'm seeing during boot but not later (xmon (ppc kernel debugger) doesn't
> > > see it if I do 'echo x > /proc/sysrq-trigger') .  I wouldn't say
> > > it's "very early boot".  It's a secondary CPU coming up and the primary
> > > is waiting for it.  We've already configured the console when this
> > > happens.
> > 
> > Sounds like an early boot console.
> > 
> > >> > The output of 'dmesg' later looks always correct, right?
> > >
> > > No, dmesg also has the extra new lines: eg
> > >
> > > <4>NIP: c00000000004e234 LR: c00000000004e230 CTR: 0000000000000000
> > > <4>REGS: c00000007c3b7b50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> > > <4>MSR: 9000000000021032
> > > <4><
> > > <4>SF
> > > <4>,HV
> > > <4>,ME
> > > <4>,IR
> > > <4>,DR
> > > <4>,RI
> > > <4>>
> > > <4>  CR: 28000042  XER: 22000000
> > 
> > Can you please paste the output of /dev/kmsg of this section? So we
> > can see the timestamps and what really went into the record buffer.
> 
> Sure.
> 
> 4,89,24561;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> 4,90,24576;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> 4,91,24583;MSR: 9000000000021032 
> 4,92,24586;<
> 4,93,24591;SF
> 4,94,24596;,HV
> 4,95,24601;,ME
> 4,96,24606;,IR
> 4,97,24611;,DR
> 4,98,24616;,RI
> 4,99,24619;>
> 4,100,24628;  CR: 28000042  XER: 22000000

FWIW, compiling with the parent commit gives this:

4,89,1712;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
4,90,1713;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
4,91,1716;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 22000082  XER: 02000000

Mikey

> 
> > 
> > >> Could you possibly try this patch?
> > >
> > > Sorry, doesn't help.  It also reprints the entire boot log to the
> > > console once the console get inited.
> > 
> > Which is the normal behaviour to do that, right? We should not have
> > touched any of that logic.
> 
> Not until this patch you asked me to try.  Hence why I noted it.  
> 
> Mikey

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Fri, Jul 6, 2012 at 5:47 AM, Michael Neuling <mikey@neuling.org> wrote:

>> 4,89,24561;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
>> 4,90,24576;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
>> 4,91,24583;MSR: 9000000000021032
>> 4,92,24586;<
>> 4,93,24591;SF
>> 4,94,24596;,HV
>> 4,95,24601;,ME
>> 4,96,24606;,IR
>> 4,97,24611;,DR
>> 4,98,24616;,RI
>> 4,99,24619;>
>> 4,100,24628;  CR: 28000042  XER: 22000000
>
> FWIW, compiling with the parent commit gives this:
>
> 4,89,1712;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> 4,90,1713;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> 4,91,1716;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 22000082  XER: 02000000

Hmm, I don't understand, which parent commit do you mean? You maybe
mean without 084681d?

I think it's a race of the two CPUs printing continuation lines, and
the continuation buffer is still occupied with data from one CPU and
not available to the other one at the same time.

What you see is likely not the direct output to the console (that
would work) but the replay of the stored buffer when the console is
registered. Because the cont buffer was still busy with one CPU, the
other thread needs to store the continuation line prints in individual
records, which leads to the (unwanted) printed newlines when
replaying.

The data we store looks all fine, it just looks needlessly separated
when we replay fromt he buffer on a newly registered boot console. We
need to merge the lines in the output, so they *look* like they are
all in one line. I'll work on a fix for that now.

Thanks,
Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Fri, Jul 6, 2012 at 12:46 PM, Kay Sievers <kay@vrfy.org> wrote:
> On Fri, Jul 6, 2012 at 5:47 AM, Michael Neuling <mikey@neuling.org> wrote:
>
>>> 4,89,24561;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
>>> 4,90,24576;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
>>> 4,91,24583;MSR: 9000000000021032
>>> 4,92,24586;<
>>> 4,93,24591;SF
>>> 4,94,24596;,HV
>>> 4,95,24601;,ME
>>> 4,96,24606;,IR
>>> 4,97,24611;,DR
>>> 4,98,24616;,RI
>>> 4,99,24619;>
>>> 4,100,24628;  CR: 28000042  XER: 22000000
>>
>> FWIW, compiling with the parent commit gives this:
>>
>> 4,89,1712;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
>> 4,90,1713;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
>> 4,91,1716;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 22000082  XER: 02000000
>
> Hmm, I don't understand, which parent commit do you mean? You maybe
> mean without 084681d?
>
> I think it's a race of the two CPUs printing continuation lines, and
> the continuation buffer is still occupied with data from one CPU and
> not available to the other one at the same time.
>
> What you see is likely not the direct output to the console (that
> would work) but the replay of the stored buffer when the console is
> registered. Because the cont buffer was still busy with one CPU, the
> other thread needs to store the continuation line prints in individual
> records, which leads to the (unwanted) printed newlines when
> replaying.
>
> The data we store looks all fine, it just looks needlessly separated
> when we replay fromt he buffer on a newly registered boot console. We
> need to merge the lines in the output, so they *look* like they are
> all in one line. I'll work on a fix for that now.

It could be that the console semaphore is still help by the other CPU,
for whatever reason, when your box runs into this situation.

Mind pasting more context (/dev/kmsg) of the log when this happens,
not only the one line that get split-up?

Is this possibly during an oops or backtrace going on when you see
this? Which code calls show_regs() here?

Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Kay Sievers <kay@vrfy.org> wrote:

> On Fri, Jul 6, 2012 at 12:46 PM, Kay Sievers <kay@vrfy.org> wrote:
> > On Fri, Jul 6, 2012 at 5:47 AM, Michael Neuling <mikey@neuling.org> wrote:
> >
> >>> 4,89,24561;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> >>> 4,90,24576;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> >>> 4,91,24583;MSR: 9000000000021032
> >>> 4,92,24586;<
> >>> 4,93,24591;SF
> >>> 4,94,24596;,HV
> >>> 4,95,24601;,ME
> >>> 4,96,24606;,IR
> >>> 4,97,24611;,DR
> >>> 4,98,24616;,RI
> >>> 4,99,24619;>
> >>> 4,100,24628;  CR: 28000042  XER: 22000000
> >>
> >> FWIW, compiling with the parent commit gives this:
> >>
> >> 4,89,1712;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
> >> 4,90,1713;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
> >> 4,91,1716;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 22000082  XER: 02000000
> >
> > Hmm, I don't understand, which parent commit do you mean? You maybe
> > mean without 084681d?
> >
> > I think it's a race of the two CPUs printing continuation lines, and
> > the continuation buffer is still occupied with data from one CPU and
> > not available to the other one at the same time.
> >
> > What you see is likely not the direct output to the console (that
> > would work) but the replay of the stored buffer when the console is
> > registered. Because the cont buffer was still busy with one CPU, the
> > other thread needs to store the continuation line prints in individual
> > records, which leads to the (unwanted) printed newlines when
> > replaying.
> >
> > The data we store looks all fine, it just looks needlessly separated
> > when we replay fromt he buffer on a newly registered boot console. We
> > need to merge the lines in the output, so they *look* like they are
> > all in one line. I'll work on a fix for that now.
> 
> It could be that the console semaphore is still help by the other CPU,
> for whatever reason, when your box runs into this situation.
> 
> Mind pasting more context (/dev/kmsg) of the log when this happens,
> not only the one line that get split-up?
> 
> Is this possibly during an oops or backtrace going on when you see
> this? Which code calls show_regs() here?

Whole kmsg below.

It is a backtrace.  

It's a warning in
arch/powerpc/sysdev/xics/xics-common.c:xics_set_cpu_giq().  The firmware
this machine is running on is non standard (Bare Metal Linux in the
lab).  The warning itself not an issue.  We've had it for years and it
tells us that our firmware/RTAS is not fully implemented.

Mikey

7,0,0;Allocated 917504 bytes for 1024 pacas at c00000000ff20000
6,1,0;Using pSeries machine description
7,2,0;Page orders: linear mapping = 24, virtual = 16, io = 12, vmemmap = 24
6,3,0;Using 1TB segments
4,4,0;Found initrd at 0xc000000002da5000:0xc00000000bc8c200
6,5,0;CPU maps initialized for 2 threads per core
7,6,0; (thread shift is 1)
7,7,0;Freed 851968 bytes for unused pacas
4,8,0;Starting Linux PPC64 #100 SMP Sat Jul 7 06:55:43 EST 2012
4,9,0;-----------------------------------------------------
4,10,0;ppc64_pft_size                = 0x0
4,11,0;physicalMemorySize            = 0x80000000
4,12,0;htab_address                  = 0xc00000007fe00000
4,13,0;htab_hash_mask                = 0x3fff
4,14,0;-----------------------------------------------------
6,15,0;Initializing cgroup subsys cpuset
5,16,0;Linux version 3.5.0-rc4-mikey (mikey@ka1) (gcc version 4.6.0 (GCC) ) #100 SMP Sat Jul 7 06:55:43 EST 2012
4,17,0;[boot]0012 Setup Arch
7,18,0;Node 0 Memory: 0x0-0x80000000
6,19,0;Section 1 and 127 (node 0) have a circular dependency on usemap and pgdat allocations
4,20,0;pseries_eeh_init: RTAS service <ibm, set-slot-reset> invalid
4,21,0;eeh_init: Failed to call platform init function (-22)
4,22,0;Zone ranges:
4,23,0;  DMA      [mem 0x00000000-0x7fffffff]
4,24,0;  Normal   empty
4,25,0;Movable zone start for each node
4,26,0;Early memory node ranges
4,27,0;  node   0: [mem 0x00000000-0x7fffffff]
7,28,0;On node 0 totalpages: 32768
7,29,0;  DMA zone: 28 pages used for memmap
7,30,0;  DMA zone: 0 pages reserved
7,31,0;  DMA zone: 32740 pages, LIFO batch:1
4,32,0;[boot]0015 Setup Done
6,33,0;PERCPU: Embedded 2 pages/cpu @c000000000e00000 s84224 r0 d46848 u524288
7,34,0;pcpu-alloc: s84224 r0 d46848 u524288 alloc=1*1048576
7,35,0;pcpu-alloc: [0] 0 1 
4,36,0;Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32740
4,37,0;Policy zone: DMA
5,38,0;Kernel command line: ipr.enabled=0
6,39,0;PID hash table entries: 4096 (order: -1, 32768 bytes)
4,40,0;freeing bootmem node 0
6,41,0;Memory: 1916096k/2097152k available (11200k kernel code, 181056k reserved, 1728k data, 1041k bss, 576k init)
6,42,0;SLUB: Genslabs=19, HWalign=128, Order=0-3, MinObjects=0, CPUs=2, Nodes=256
6,43,0;Hierarchical RCU implementation.
6,44,0;NR_IRQS:512 nr_irqs:512 16
4,45,0;set-indicator(9005, 0, 1) returned -22
4,46,0;------------[ cut here ]------------
4,47,0;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
4,48,0;Modules linked in:
4,49,0;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
4,50,0;REGS: c000000000c27ae0 TRAP: 0700   Not tainted  (3.5.0-rc4-mikey)
4,51,0;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 24000042  XER: 22000000
4,52,0;SOFTE: 0
4,53,0;CFAR: c000000000740438
4,54,0;TASK = c000000000b2dd80[0] 'swapper/0' THREAD: c000000000c24000 CPU: 0\x0aGPR00: c000000000048160 c000000000c27d60 c000000000c24488 0000000000000026 \x0aGPR04: 0000000000000000 000000000000002e 30352c2000000000 0000000032320000 \x0aGPR08: 2920726500000000 c000000000b30e20 0000000000000020 000000000000002e \x0aGPR12: 0000000024000042 c00000000ff20000 0000000000000000 0000000000000000 \x0aGPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 \x0aGPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 \x0aGPR24: 0000000000000000 0000000000000000 0000000000000000 c000000000dd8080 \x0aGPR28: c000000000cb0628 0000000000000000 c000000000b70a28 0000000000000001 
4,55,0;NIP [c000000000048164] .xics_set_cpu_giq+0xb4/0xc0
4,56,0;LR [c000000000048160] .xics_set_cpu_giq+0xb0/0xc0
4,57,0;Call Trace:
4,58,0;[c000000000c27d60] [c000000000048160] .xics_set_cpu_giq+0xb0/0xc0 (unreliable)
4,59,0;[c000000000c27df0] [c000000000a75b90] .pseries_xics_init_IRQ+0x10/0x24
4,60,0;[c000000000c27e60] [c000000000a643cc] .init_IRQ+0x3c/0x54
4,61,0;[c000000000c27ee0] [c000000000a60804] .start_kernel+0x250/0x464
4,62,0;[c000000000c27f90] [c00000000000967c] .start_here_common+0x20/0x24
4,63,0;Instruction dump:
4,64,0;7fa4eb78 4bfddd49 60000000 2f830000 7c671b78 409cffa4 e87e8030 3880232d 
4,65,0;7fa5eb78 7fe6fb78 486f8289 60000000 <0fe00000> 4bffff84 60000000 7c0802a6 
4,66,0;---[ end trace 31fd0ba7d8756001 ]---
7,67,0;pic: no ISA interrupt controller
4,68,0;error: reading the clock failed (-1)
7,69,0;time_init: decrementer frequency = 59.375000 MHz
7,70,0;time_init: processor frequency   = 3800.000000 MHz
6,71,0;clocksource: timebase mult[86bca1b] shift[23] registered
7,72,0;clockevent: decrementer mult[f333333] shift[32] cpu[0]
6,73,0;Console: colour dummy device 80x25
6,74,0;console [tty0] enabled
6,75,0;console [hvc0] enabled
6,76,4785;pid_max: default: 32768 minimum: 301
6,77,5419;Dentry cache hash table entries: 262144 (order: 5, 2097152 bytes)
6,78,14588;Inode-cache hash table entries: 131072 (order: 4, 1048576 bytes)
6,79,19200;Mount-cache hash table entries: 4096
6,80,22334;Initializing cgroup subsys cpuacct
6,81,22418;Initializing cgroup subsys devices
6,82,22504;Initializing cgroup subsys freezer
6,83,23005;POWER7 performance monitor hardware support registered
6,84,24392;Firmware doesn't support query-cpu-stopped-state
4,85,24518;set-indicator(9005, 0, 1) returned -22
4,86,24534;------------[ cut here ]------------
4,87,24545;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
4,88,24549;Modules linked in:
4,89,24565;NIP: c000000000048164 LR: c000000000048160 CTR: 0000000000000000
4,90,24579;REGS: c00000007e59fb50 TRAP: 0700   Tainted: G        W     (3.5.0-rc4-mikey)
4,91,24586;MSR: 9000000000021032 
4,92,24590;<
4,93,24594;SF
4,94,24599;,HV
4,95,24604;,ME
4,96,24609;,IR
4,97,24614;,DR
4,98,24619;,RI
4,99,24623;>
4,100,24631;  CR: 28000042  XER: 22000000
4,101,24637;SOFTE: 0
4,102,24643;CFAR: c000000000740438
4,103,24656;TASK = c00000007e56bb40[0] 'swapper/1' THREAD: c00000007e59c000
4,104,24661; CPU: 1
4,105,24667;\x0aGPR00: 
4,106,24673;c000000000048160 
4,107,24679;c00000007e59fdd0 
4,108,24685;c000000000c24488 
4,109,24691;0000000000000026 
4,110,24696;\x0aGPR04: 
4,111,24701;0000000000000000 
4,112,24707;0000000000000002 
4,113,24713;c000000000cd011c 
4,114,24719;302c203129207265 
4,115,24724;\x0aGPR08: 
4,116,24730;7475726e00000000 
4,117,24736;0000000000000000 
4,118,24741;0000000000000000 
4,119,24746;0000000000000000 
4,120,24752;\x0aGPR12: 
4,121,24758;0000000028000042 
4,122,24764;c00000000ff20380 
4,123,24770;c00000007e59ff90 
4,124,24775;0000000000000000 
4,125,24781;\x0aGPR16: 
4,126,24786;0000000000000000 
4,127,24792;0000000000000000 
4,128,24797;0000000000000000 
4,129,24802;0000000000000000 
4,130,24808;\x0aGPR20: 
4,131,24813;0000000000000000 
4,132,24818;0000000000000000 
4,133,24824;0000000000000000 
4,134,24829;0000000000000001 
4,135,24835;\x0aGPR24: 
4,136,24840;0000000000000001 
4,137,24845;0000000000000000 
4,138,24851;0000000000000000 
4,139,24856;0000000000000001 
4,140,24862;\x0aGPR28: 
4,141,24867;0000000000000008 
4,142,24872;0000000000000000 
4,143,24878;c000000000b70a28 
4,144,24884;0000000000000001 
4,145,24887;
4,146,24907;NIP [c000000000048164] .xics_set_cpu_giq+0xb4/0xc0
4,147,24927;LR [c000000000048160] .xics_set_cpu_giq+0xb0/0xc0
4,148,24931;Call Trace:
4,149,24953;[c00000007e59fdd0] [c000000000048160] .xics_set_cpu_giq+0xb0/0xc0
4,150,24957; (unreliable)
4,151,24961;
4,152,24986;[c00000007e59fe60] [c00000000076768c] .smp_xics_setup_cpu+0x28/0xbc
4,153,24989;
4,154,25013;[c00000007e59fee0] [c000000000764308] .start_secondary+0xc8/0x360
4,155,25017;
4,156,25040;[c00000007e59ff90] [c00000000000936c] .start_secondary_prolog+0x10/0x14
4,157,25043;
4,158,25048;Instruction dump:
4,159,25052;
4,160,25058;7fa4eb78 
4,161,25064;4bfddd49 
4,162,25070;60000000 
4,163,25076;2f830000 
4,164,25082;7c671b78 
4,165,25088;409cffa4 
4,166,25094;e87e8030 
4,167,25100;3880232d 
4,168,25104;
4,169,25110;7fa5eb78 
4,170,25116;7fe6fb78 
4,171,25122;486f8289 
4,172,25128;60000000 
4,173,25134;<0fe00000> 
4,174,25141;4bffff84 
4,175,25147;60000000 
4,176,25153;7c0802a6 
4,177,25156;
4,178,25164;---[ end trace 31fd0ba7d8756002 ]---
6,179,25465;Brought up 2 CPUs
7,180,29974;Node 0 CPUs: 0-1
6,181,30219;Enabling Asymmetric SMT scheduling
6,182,106522;NET: Registered protocol family 16
6,183,106731;IBM eBus Device Driver
4,184,107916;kworker/u:0 (16) used greatest stack depth: 12800 bytes left
6,185,120011;nvram: No room to create ibm,rtas-log partition, deleting any obsolete OS partitions...
3,186,120204;nvram: Failed to find or create ibm,rtas-log partition, err -28
6,187,120344;nvram: No room to create lnx,oops-log partition, deleting any obsolete OS partitions...
3,188,120536;nvram: Failed to find or create lnx,oops-log partition, err -28
6,189,120694;CPU Hotplug not supported by firmware - disabling.
6,190,126948;PCI: Probing PCI hardware
7,191,127017;PCI: Probing PCI hardware done
4,192,127028;opal: Node not found
6,193,296438;bio: create slab <bio-0> at 0
6,194,300573;vgaarb: loaded
5,195,303929;SCSI subsystem initialized
7,196,307408;libata version 3.00 loaded.
6,197,312421;usbcore: registered new interface driver usbfs
6,198,313151;usbcore: registered new interface driver hub
6,199,314645;usbcore: registered new device driver usb
6,200,322114;Switching to clocksource timebase
4,201,352608;kworker/u:0 (223) used greatest stack depth: 11168 bytes left
6,202,432888;NET: Registered protocol family 2
6,203,433315;IP route cache hash table entries: 16384 (order: 1, 131072 bytes)
6,204,434295;TCP established hash table entries: 65536 (order: 4, 1048576 bytes)
6,205,438160;TCP bind hash table entries: 65536 (order: 4, 1048576 bytes)
6,206,441363;TCP: Hash tables configured (established 65536 bind 65536)
6,207,441491;TCP: reno registered
6,208,441565;UDP hash table entries: 2048 (order: 0, 65536 bytes)
6,209,441978;UDP-Lite hash table entries: 2048 (order: 0, 65536 bytes)
6,210,442727;NET: Registered protocol family 1
6,211,443753;RPC: Registered named UNIX socket transport module.
6,212,443869;RPC: Registered udp transport module.
6,213,443958;RPC: Registered tcp transport module.
6,214,444049;RPC: Registered tcp NFSv4.1 backchannel transport module.
7,215,444178;PCI: CLS 0 bytes, default 128
6,216,444401;Trying to unpack rootfs image as initramfs...
6,217,2011859;Freeing initrd memory: 146368k freed
6,218,2019359;rtasd: No event-scan on system
6,219,2020743;Hypercall H_BEST_ENERGY not supported
6,220,2025601;audit: initializing netlink socket (disabled)
5,221,2025727;type=2000 audit(2.020:1): initialized
6,222,2992853;HugeTLB registered 1 MB page size, pre-allocated 0 pages
6,223,2992982;HugeTLB registered 16 MB page size, pre-allocated 0 pages
6,224,2993112;HugeTLB registered 16 GB page size, pre-allocated 0 pages
5,225,3109094;NFS: Registering the id_resolver key type
5,226,3109219;Key type id_resolver registered
6,227,3112591;msgmni has been set to 4028
6,228,3117312;Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
6,229,3117460;io scheduler noop registered
6,230,3117534;io scheduler deadline registered
6,231,3118446;io scheduler cfq registered (default)
6,232,3692669;Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
6,233,3703393;Generic RTC Driver v1.07
6,234,3748115;brd: module loaded
6,235,3770441;loop: module loaded
6,236,3770496;Uniform Multi-Platform E-IDE driver
6,237,3774960;ide-gd driver 1.18
6,238,3776029;ide-cd driver 5.00
6,239,3787095;ipr: IBM Power RAID SCSI Device Driver version: 2.5.3 (March 10, 2012)
6,240,3788311;st: Version 20101219, fixed bufsize 32768, s/g segs 256
6,241,3796157;pcnet32: pcnet32.c:v1.35 21.Apr.2008 tsbogend@alpha.franken.de
7,242,3798393;ibmveth: IBM Power Virtual Ethernet Driver 1.04
6,243,3799456;ehea: IBM eHEA ethernet device driver (Release EHEA_0107)
6,244,3801948;e100: Intel(R) PRO/100 Network Driver, 3.5.24-k2-NAPI
6,245,3802068;e100: Copyright(c) 1999-2006 Intel Corporation
6,246,3803197;e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
6,247,3803337;e1000: Copyright (c) 1999-2006 Intel Corporation.
6,248,3804513;e1000e: Intel(R) PRO/1000 Network Driver - 2.0.0-k
6,249,3804625;e1000e: Copyright(c) 1999 - 2012 Intel Corporation.
6,250,3805823;ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
6,251,3807019;ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
6,252,3809276;mousedev: PS/2 mouse device common for all mice
6,253,3812135;md: linear personality registered for level -1
6,254,3812243;md: raid0 personality registered for level 0
6,255,3812348;md: raid1 personality registered for level 1
6,256,3814922;device-mapper: ioctl: 4.22.0-ioctl (2011-10-19) initialised: dm-devel@redhat.com
6,257,3815091;cpuidle: using governor ladder
6,258,3815168;cpuidle: using governor menu
6,259,3837236;usbcore: registered new interface driver usbhid
6,260,3837342;usbhid: USB HID core driver
7,261,3837414;oprofile: using ppc64/power7 performance monitoring.
6,262,3837813;IPv4 over IPv4 tunneling driver
6,263,3841830;TCP: cubic registered
6,264,3841891;NET: Registered protocol family 17
5,265,3842089;Key type dns_resolver registered
7,266,3842319;Running code patching self-tests ...
7,267,3846278;Running feature fixup self-tests ...
7,268,3846308;Running MSI bitmap self-tests ...
6,269,3875364;registered taskstats version 1
6,270,3876407;console [netcon0] enabled
6,271,3876473;netconsole: network logging started
6,272,3877574;Freeing unused kernel memory: 576k freed
4,273,3889441;modprobe (1071) used greatest stack depth: 11120 bytes left
4,274,4403534;udevd (1108) used greatest stack depth: 10528 bytes left
4,275,4416293;tput (1111) used greatest stack depth: 10464 bytes left
4,276,4777038;blkid (1149) used greatest stack depth: 10288 bytes left
4,277,6012331;fsck (1224) used greatest stack depth: 10224 bytes left
4,278,7298006;run-parts (1346) used greatest stack depth: 9968 bytes left
4,279,9235784;sshd (1497): /proc/1497/oom_adj is deprecated, please use /proc/1497/oom_score_adj instead.

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Sat, 2012-07-07 at 07:04 +1000, Michael Neuling wrote:
> Whole kmsg below.

I guess I have an idea now what's going on.

> 4,47,0;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> 4,51,0;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 24000042  XER: 22000000
> 4,54,0;TASK = c000000000b2dd80[0] 'swapper/0' THREAD: c000000000c24000 CPU: 0

This is the warning on CPU#1, all fine, all in one line.

> 6,74,0;console [tty0] enabled
> 6,75,0;console [hvc0] enabled

Now the boot consoles are registered, which replays the whole buffer
that was collected up to this point. During the entire time the console
semaphore needs to be held, and this can be quite a while.

> 4,87,24545;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> \4,91,24586;MSR: 9000000000021032 
> 4,92,24590;<
> 4,93,24594;SF
> 4,94,24599;,HV
> 4,95,24604;,ME
> 4,96,24609;,IR
> 4,97,24614;,DR
> 4,98,24619;,RI
> 4,99,24623;>
> 4,104,24661; CPU: 1

At the same time the CPU#2 prints the same warning with a continuation
line, but the buffer from CPU#1 can not be flushed to the console, nor
can the continuation line printk()s from CPU#2 be merged at this point.
The consoles are still locked and busy with replaying the old log
messages, so the new continuation data is just stored away in the record
buffer as it is coming in.
If the console would be registered a bit earlier, or the warning would
happen a bit later, we would probably not see any of this.

I can fake something like this just by holding the console semaphore
over a longer time and printing continuation lines with different CPUs
in a row.

The patch below seems to work for me. It is also here:
  http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD

It only applies cleanly on top of this patch:
  http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD

Thanks,
Kay


Subject: kmsg: merge continuation records while printing

In (the unlikely) case our continuation merge buffer is busy, we unfortunately
can not merge further continuation printk()s into a single record and have to
store them separately, which leads to split-up output of these lines when they
are printed.

Add some flags about newlines and prefix existence to these records and try to
reconstruct the full line again, when the separated records are printed.
---
 kernel/printk.c |  119 ++++++++++++++++++++++++++++++++++++--------------------
 1 file changed, 77 insertions(+), 42 deletions(-)

--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -194,8 +194,10 @@ static int console_may_schedule;
  */
 
 enum log_flags {
-	LOG_DEFAULT = 0,
-	LOG_NOCONS = 1,		/* already flushed, do not print to console */
+	LOG_NOCONS	= 1,	/* already flushed, do not print to console */
+	LOG_NEWLINE	= 2,	/* text ended with a newline */
+	LOG_PREFIX	= 4,	/* text started with a prefix */
+	LOG_CONT	= 8,	/* text is a fragment of a continuation line */
 };
 
 struct log {
@@ -217,6 +219,7 @@ static DEFINE_RAW_SPINLOCK(logbuf_lock);
 /* the next printk record to read by syslog(READ) or /proc/kmsg */
 static u64 syslog_seq;
 static u32 syslog_idx;
+static enum log_flags syslog_prev;
 static size_t syslog_partial;
 
 /* index and sequence number of the first record stored in the buffer */
@@ -839,8 +842,8 @@ static size_t print_prefix(const struct
 	return len;
 }
 
-static size_t msg_print_text(const struct log *msg, bool syslog,
-			     char *buf, size_t size)
+static size_t msg_print_text(const struct log *msg, enum log_flags prev,
+			     bool syslog, char *buf, size_t size)
 {
 	const char *text = log_text(msg);
 	size_t text_size = msg->text_len;
@@ -849,6 +852,8 @@ static size_t msg_print_text(const struc
 	do {
 		const char *next = memchr(text, '\n', text_size);
 		size_t text_len;
+		bool prefix = true;
+		bool newline = true;
 
 		if (next) {
 			text_len = next - text;
@@ -858,19 +863,35 @@ static size_t msg_print_text(const struc
 			text_len = text_size;
 		}
 
+		if ((prev & LOG_CONT) && !(msg->flags & LOG_PREFIX))
+			prefix = false;
+
+		if (msg->flags & LOG_CONT) {
+			if ((prev & LOG_CONT) && !(prev & LOG_NEWLINE))
+				prefix = false;
+
+			if (!(msg->flags & LOG_NEWLINE))
+				newline = false;
+		}
+
 		if (buf) {
 			if (print_prefix(msg, syslog, NULL) +
 			    text_len + 1>= size - len)
 				break;
 
-			len += print_prefix(msg, syslog, buf + len);
+			if (prefix)
+				len += print_prefix(msg, syslog, buf + len);
 			memcpy(buf + len, text, text_len);
 			len += text_len;
-			buf[len++] = '\n';
+			if (newline)
+				buf[len++] = '\n';
 		} else {
 			/* SYSLOG_ACTION_* buffer size only calculation */
-			len += print_prefix(msg, syslog, NULL);
-			len += text_len + 1;
+			if (prefix)
+				len += print_prefix(msg, syslog, NULL);
+			len += text_len;
+			if (newline)
+				len++;
 		}
 
 		text = next;
@@ -898,6 +919,7 @@ static int syslog_print(char __user *buf
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
+			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (syslog_seq == log_next_seq) {
@@ -907,11 +929,12 @@ static int syslog_print(char __user *buf
 
 		skip = syslog_partial;
 		msg = log_from_idx(syslog_idx);
-		n = msg_print_text(msg, true, text, LOG_LINE_MAX);
+		n = msg_print_text(msg, syslog_prev, true, text, LOG_LINE_MAX);
 		if (n - syslog_partial <= size) {
 			/* message fits into buffer, move forward */
 			syslog_idx = log_next(syslog_idx);
 			syslog_seq++;
+			syslog_prev = msg->flags;
 			n -= syslog_partial;
 			syslog_partial = 0;
 		} else if (!len){
@@ -954,6 +977,7 @@ static int syslog_print_all(char __user
 		u64 next_seq;
 		u64 seq;
 		u32 idx;
+		enum log_flags prev;
 
 		if (clear_seq < log_first_seq) {
 			/* messages are gone, move to first available one */
@@ -967,10 +991,11 @@ static int syslog_print_all(char __user
 		 */
 		seq = clear_seq;
 		idx = clear_idx;
+		prev = 0;
 		while (seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len += msg_print_text(msg, true, NULL, 0);
+			len += msg_print_text(msg, prev, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -978,10 +1003,11 @@ static int syslog_print_all(char __user
 		/* move first record forward until length fits into the buffer */
 		seq = clear_seq;
 		idx = clear_idx;
+		prev = 0;
 		while (len > size && seq < log_next_seq) {
 			struct log *msg = log_from_idx(idx);
 
-			len -= msg_print_text(msg, true, NULL, 0);
+			len -= msg_print_text(msg, prev, true, NULL, 0);
 			idx = log_next(idx);
 			seq++;
 		}
@@ -990,17 +1016,19 @@ static int syslog_print_all(char __user
 		next_seq = log_next_seq;
 
 		len = 0;
+		prev = 0;
 		while (len >= 0 && seq < next_seq) {
 			struct log *msg = log_from_idx(idx);
 			int textlen;
 
-			textlen = msg_print_text(msg, true, text, LOG_LINE_MAX);
+			textlen = msg_print_text(msg, prev, true, text, LOG_LINE_MAX);
 			if (textlen < 0) {
 				len = textlen;
 				break;
 			}
 			idx = log_next(idx);
 			seq++;
+			prev = msg->flags;
 
 			raw_spin_unlock_irq(&logbuf_lock);
 			if (copy_to_user(buf + len, text, textlen))
@@ -1013,6 +1041,7 @@ static int syslog_print_all(char __user
 				/* messages are gone, move to next one */
 				seq = log_first_seq;
 				idx = log_first_idx;
+				prev = 0;
 			}
 		}
 	}
@@ -1117,6 +1146,7 @@ int do_syslog(int type, char __user *buf
 			/* messages are gone, move to first one */
 			syslog_seq = log_first_seq;
 			syslog_idx = log_first_idx;
+			syslog_prev = 0;
 			syslog_partial = 0;
 		}
 		if (from_file) {
@@ -1127,18 +1157,18 @@ int do_syslog(int type, char __user *buf
 			 */
 			error = log_next_idx - syslog_idx;
 		} else {
-			u64 seq;
-			u32 idx;
+			u64 seq = syslog_seq;
+			u32 idx = syslog_idx;
+			enum log_flags prev = syslog_prev;
 
 			error = 0;
-			seq = syslog_seq;
-			idx = syslog_idx;
 			while (seq < log_next_seq) {
 				struct log *msg = log_from_idx(idx);
 
-				error += msg_print_text(msg, true, NULL, 0);
+				error += msg_print_text(msg, prev, true, NULL, 0);
 				idx = log_next(idx);
 				seq++;
+				prev = msg->flags;
 			}
 			error -= syslog_partial;
 		}
@@ -1408,10 +1438,9 @@ asmlinkage int vprintk_emit(int facility
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
 	size_t text_len;
+	enum log_flags lflags = 0;
 	unsigned long flags;
 	int this_cpu;
-	bool newline = false;
-	bool prefix = false;
 	int printed_len = 0;
 
 	boot_delay_msec();
@@ -1450,7 +1479,7 @@ asmlinkage int vprintk_emit(int facility
 		recursion_bug = 0;
 		printed_len += strlen(recursion_msg);
 		/* emit KERN_CRIT message */
-		log_store(0, 2, LOG_DEFAULT, 0,
+		log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
 			  NULL, 0, recursion_msg, printed_len);
 	}
 
@@ -1463,7 +1492,7 @@ asmlinkage int vprintk_emit(int facility
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
 		text_len--;
-		newline = true;
+		lflags |= LOG_NEWLINE;
 	}
 
 	/* strip syslog prefix and extract log level or control flags */
@@ -1473,7 +1502,7 @@ asmlinkage int vprintk_emit(int facility
 			if (level == -1)
 				level = text[1] - '0';
 		case 'd':	/* KERN_DEFAULT */
-			prefix = true;
+			lflags |= LOG_PREFIX;
 		case 'c':	/* KERN_CONT */
 			text += 3;
 			text_len -= 3;
@@ -1483,22 +1512,20 @@ asmlinkage int vprintk_emit(int facility
 	if (level == -1)
 		level = default_message_loglevel;
 
-	if (dict) {
-		prefix = true;
-		newline = true;
-	}
+	if (dict)
+		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	if (!newline) {
+	if (!(lflags & LOG_NEWLINE)) {
 		/*
 		 * Flush the conflicting buffer. An earlier newline was missing,
 		 * or another task also prints continuation lines.
 		 */
-		if (cont.len && (prefix || cont.owner != current))
+		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
 			cont_flush();
 
 		/* buffer line if possible, otherwise store it right away */
 		if (!cont_add(facility, level, text, text_len))
-			log_store(facility, level, LOG_DEFAULT, 0,
+			log_store(facility, level, lflags | LOG_CONT, 0,
 				  dict, dictlen, text, text_len);
 	} else {
 		bool stored = false;
@@ -1510,13 +1537,13 @@ asmlinkage int vprintk_emit(int facility
 		 * flush it out and store this line separately.
 		 */
 		if (cont.len && cont.owner == current) {
-			if (!prefix)
+			if (!(lflags & LOG_PREFIX))
 				stored = cont_add(facility, level, text, text_len);
 			cont_flush();
 		}
 
 		if (!stored)
-			log_store(facility, level, LOG_DEFAULT, 0,
+			log_store(facility, level, lflags, 0,
 				  dict, dictlen, text, text_len);
 	}
 	printed_len += text_len;
@@ -1615,8 +1642,8 @@ static struct cont {
 static struct log *log_from_idx(u32 idx) { return NULL; }
 static u32 log_next(u32 idx) { return 0; }
 static void call_console_drivers(int level, const char *text, size_t len) {}
-static size_t msg_print_text(const struct log *msg, bool syslog,
-			     char *buf, size_t size) { return 0; }
+static size_t msg_print_text(const struct log *msg, enum log_flags prev,
+			     bool syslog, char *buf, size_t size) { return 0; }
 static size_t cont_print_text(char *text, size_t size) { return 0; }
 
 #endif /* CONFIG_PRINTK */
@@ -1892,6 +1919,7 @@ void wake_up_klogd(void)
 /* the next printk record to write to the console */
 static u64 console_seq;
 static u32 console_idx;
+static enum log_flags console_prev;
 
 /**
  * console_unlock - unlock the console system
@@ -1952,6 +1980,7 @@ again:
 			/* messages are gone, move to first one */
 			console_seq = log_first_seq;
 			console_idx = log_first_idx;
+			console_prev = 0;
 		}
 skip:
 		if (console_seq == log_next_seq)
@@ -1975,10 +2004,11 @@ skip:
 		}
 
 		level = msg->level;
-		len = msg_print_text(msg, false, text, sizeof(text));
-
+		len = msg_print_text(msg, console_prev, false,
+				     text, sizeof(text));
 		console_idx = log_next(console_idx);
 		console_seq++;
+		console_prev = msg->flags;
 		raw_spin_unlock(&logbuf_lock);
 
 		stop_critical_timings();	/* don't trace print latency */
@@ -2241,6 +2271,7 @@ void register_console(struct console *ne
 		raw_spin_lock_irqsave(&logbuf_lock, flags);
 		console_seq = syslog_seq;
 		console_idx = syslog_idx;
+		console_prev = syslog_prev;
 		raw_spin_unlock_irqrestore(&logbuf_lock, flags);
 		/*
 		 * We're about to replay the log buffer.  Only do this to the
@@ -2534,8 +2565,7 @@ bool kmsg_dump_get_line(struct kmsg_dump
 	}
 
 	msg = log_from_idx(dumper->cur_idx);
-	l = msg_print_text(msg, syslog,
-			      line, size);
+	l = msg_print_text(msg, 0, syslog, line, size);
 
 	dumper->cur_idx = log_next(dumper->cur_idx);
 	dumper->cur_seq++;
@@ -2575,6 +2605,7 @@ bool kmsg_dump_get_buffer(struct kmsg_du
 	u32 idx;
 	u64 next_seq;
 	u32 next_idx;
+	enum log_flags prev;
 	size_t l = 0;
 	bool ret = false;
 
@@ -2597,23 +2628,27 @@ bool kmsg_dump_get_buffer(struct kmsg_du
 	/* calculate length of entire buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
+	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, true, NULL, 0);
+		l += msg_print_text(msg, prev, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
+		prev = msg->flags;
 	}
 
 	/* move first record forward until length fits into the buffer */
 	seq = dumper->cur_seq;
 	idx = dumper->cur_idx;
+	prev = 0;
 	while (l > size && seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l -= msg_print_text(msg, true, NULL, 0);
+		l -= msg_print_text(msg, prev, true, NULL, 0);
 		idx = log_next(idx);
 		seq++;
+		prev = msg->flags;
 	}
 
 	/* last message in next interation */
@@ -2621,14 +2656,14 @@ bool kmsg_dump_get_buffer(struct kmsg_du
 	next_idx = idx;
 
 	l = 0;
+	prev = 0;
 	while (seq < dumper->next_seq) {
 		struct log *msg = log_from_idx(idx);
 
-		l += msg_print_text(msg, syslog,
-				    buf + l, size - l);
-
+		l += msg_print_text(msg, prev, syslog, buf + l, size - l);
 		idx = log_next(idx);
 		seq++;
+		prev = msg->flags;
 	}
 
 	dumper->next_seq = next_seq;

Re: [PATCH v3] printk: Have printk() never buffer its data

[Greg Kroah-Hartman]

On Sun, Jul 08, 2012 at 07:55:55PM +0200, Kay Sievers wrote:
> On Sat, 2012-07-07 at 07:04 +1000, Michael Neuling wrote:
> > Whole kmsg below.
> 
> I guess I have an idea now what's going on.
> 
> > 4,47,0;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> > 4,51,0;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 24000042  XER: 22000000
> > 4,54,0;TASK = c000000000b2dd80[0] 'swapper/0' THREAD: c000000000c24000 CPU: 0
> 
> This is the warning on CPU#1, all fine, all in one line.
> 
> > 6,74,0;console [tty0] enabled
> > 6,75,0;console [hvc0] enabled
> 
> Now the boot consoles are registered, which replays the whole buffer
> that was collected up to this point. During the entire time the console
> semaphore needs to be held, and this can be quite a while.
> 
> > 4,87,24545;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> > \4,91,24586;MSR: 9000000000021032 
> > 4,92,24590;<
> > 4,93,24594;SF
> > 4,94,24599;,HV
> > 4,95,24604;,ME
> > 4,96,24609;,IR
> > 4,97,24614;,DR
> > 4,98,24619;,RI
> > 4,99,24623;>
> > 4,104,24661; CPU: 1
> 
> At the same time the CPU#2 prints the same warning with a continuation
> line, but the buffer from CPU#1 can not be flushed to the console, nor
> can the continuation line printk()s from CPU#2 be merged at this point.
> The consoles are still locked and busy with replaying the old log
> messages, so the new continuation data is just stored away in the record
> buffer as it is coming in.
> If the console would be registered a bit earlier, or the warning would
> happen a bit later, we would probably not see any of this.
> 
> I can fake something like this just by holding the console semaphore
> over a longer time and printing continuation lines with different CPUs
> in a row.
> 
> The patch below seems to work for me. It is also here:
>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
> 
> It only applies cleanly on top of this patch:
>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
> 
> Thanks,
> Kay
> 
> 
> Subject: kmsg: merge continuation records while printing
> 
> In (the unlikely) case our continuation merge buffer is busy, we unfortunately
> can not merge further continuation printk()s into a single record and have to
> store them separately, which leads to split-up output of these lines when they
> are printed.
> 
> Add some flags about newlines and prefix existence to these records and try to
> reconstruct the full line again, when the separated records are printed.
> ---
>  kernel/printk.c |  119 ++++++++++++++++++++++++++++++++++++--------------------
>  1 file changed, 77 insertions(+), 42 deletions(-)

Michael, did this solve the issue for you?

It's a bit "big" of a patch so late in the -rc cycle, is it ok if we
just merge this in 3.6-rc1 and backport it to 3.5.1 if it looks ok
there?

thanks,

greg k-h

Re: [PATCH v3] printk: Have printk() never buffer its data

[Joe Perches]

On Mon, 2012-07-09 at 10:09 -0700, Greg Kroah-Hartman wrote:
> is it ok if we
> just merge this in 3.6-rc1 and backport it to 3.5.1 if it looks ok
> there?

I'd prefer it get accepted now so that refactoring the
printk subsystem could occur for 3.6.

Another option would be to revert all Kay's changes to the
printk subsystem, fix this in 3.6 and refactor in 3.7.

Re: [PATCH v3] printk: Have printk() never buffer its data

[Michael Neuling]

Greg Kroah-Hartman <gregkh@linuxfoundation.org> wrote:

> On Sun, Jul 08, 2012 at 07:55:55PM +0200, Kay Sievers wrote:
> > On Sat, 2012-07-07 at 07:04 +1000, Michael Neuling wrote:
> > > Whole kmsg below.
> > 
> > I guess I have an idea now what's going on.
> > 
> > > 4,47,0;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> > > 4,51,0;MSR: 9000000000021032 <SF,HV,ME,IR,DR,RI>  CR: 24000042  XER: 22000000
> > > 4,54,0;TASK = c000000000b2dd80[0] 'swapper/0' THREAD: c000000000c24000 CPU: 0
> > 
> > This is the warning on CPU#1, all fine, all in one line.
> > 
> > > 6,74,0;console [tty0] enabled
> > > 6,75,0;console [hvc0] enabled
> > 
> > Now the boot consoles are registered, which replays the whole buffer
> > that was collected up to this point. During the entire time the console
> > semaphore needs to be held, and this can be quite a while.
> > 
> > > 4,87,24545;WARNING: at /scratch/mikey/src/linux-ozlabs/arch/powerpc/sysdev/xics/xics-common.c:105
> > > \4,91,24586;MSR: 9000000000021032 
> > > 4,92,24590;<
> > > 4,93,24594;SF
> > > 4,94,24599;,HV
> > > 4,95,24604;,ME
> > > 4,96,24609;,IR
> > > 4,97,24614;,DR
> > > 4,98,24619;,RI
> > > 4,99,24623;>
> > > 4,104,24661; CPU: 1
> > 
> > At the same time the CPU#2 prints the same warning with a continuation
> > line, but the buffer from CPU#1 can not be flushed to the console, nor
> > can the continuation line printk()s from CPU#2 be merged at this point.
> > The consoles are still locked and busy with replaying the old log
> > messages, so the new continuation data is just stored away in the record
> > buffer as it is coming in.
> > If the console would be registered a bit earlier, or the warning would
> > happen a bit later, we would probably not see any of this.
> > 
> > I can fake something like this just by holding the console semaphore
> > over a longer time and printing continuation lines with different CPUs
> > in a row.
> > 
> > The patch below seems to work for me. It is also here:
> >   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
> > 
> > It only applies cleanly on top of this patch:
> >   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
> > 
> > Thanks,
> > Kay
> > 
> > 
> > Subject: kmsg: merge continuation records while printing
> > 
> > In (the unlikely) case our continuation merge buffer is busy, we unfortunately
> > can not merge further continuation printk()s into a single record and have to
> > store them separately, which leads to split-up output of these lines when they
> > are printed.
> > 
> > Add some flags about newlines and prefix existence to these records and try to
> > reconstruct the full line again, when the separated records are printed.
> > ---
> >  kernel/printk.c |  119 ++++++++++++++++++++++++++++++++++++--------------------
> >  1 file changed, 77 insertions(+), 42 deletions(-)
> 
> Michael, did this solve the issue for you?

It didn't but I've been working with Kay offline and what he pushed to
you and is now in your driver-core-linus branch is good.  ie.

  5becfb1 kmsg: merge continuation records while printing

... works for me.

Thanks,
Mikey

Re: [PATCH v3] printk: Have printk() never buffer its data

[Joe Perches]

On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote:

> At the same time the CPU#2 prints the same warning with a continuation
> line, but the buffer from CPU#1 can not be flushed to the console, nor
> can the continuation line printk()s from CPU#2 be merged at this point.
> The consoles are still locked and busy with replaying the old log
> messages, so the new continuation data is just stored away in the record
> buffer as it is coming in.
> If the console would be registered a bit earlier, or the warning would
> happen a bit later, we would probably not see any of this.
> 
> I can fake something like this just by holding the console semaphore
> over a longer time and printing continuation lines with different CPUs
> in a row.
> 
> The patch below seems to work for me. It is also here:
>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
> 
> It only applies cleanly on top of this patch:
>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
> 

Hi Kay.

I just ran a test with what's in Greg's driver-core -for-linus branch.

One of the differences in dmesg is timestamping of consecutive
	pr_<level>("foo...)
followed directly by
	pr_cont("bar...")

For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+)

# grep MAP /var/log/dm* -A1
dmesg:[    0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
dmesg-[    0.781707] ata2: port disabled--ignoring
--
dmesg.0:[    0.948881] ata_piix 0000:00:1f.2: MAP [
dmesg.0-[    0.948883]  P0 P2 P1 P3 ]

These messages originate starting at
drivers/ata/ata_piix.c:1354

All the continuations are emitted with pr_cont.

I think this output should still be coalesced without
timestamp deltas.  Perhaps the timestamping code can
still be reworked to avoid too small a delta producing
a new timestamp and another dmesg line.

cheers, Joe

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <joe@perches.com> wrote:
> On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote:
>
>> At the same time the CPU#2 prints the same warning with a continuation
>> line, but the buffer from CPU#1 can not be flushed to the console, nor
>> can the continuation line printk()s from CPU#2 be merged at this point.
>> The consoles are still locked and busy with replaying the old log
>> messages, so the new continuation data is just stored away in the record
>> buffer as it is coming in.
>> If the console would be registered a bit earlier, or the warning would
>> happen a bit later, we would probably not see any of this.
>>
>> I can fake something like this just by holding the console semaphore
>> over a longer time and printing continuation lines with different CPUs
>> in a row.
>>
>> The patch below seems to work for me. It is also here:
>>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
>>
>> It only applies cleanly on top of this patch:
>>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
>>
>
> Hi Kay.
>
> I just ran a test with what's in Greg's driver-core -for-linus branch.
>
> One of the differences in dmesg is timestamping of consecutive
>         pr_<level>("foo...)
> followed directly by
>         pr_cont("bar...")
>
> For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+)
>
> # grep MAP /var/log/dm* -A1
> dmesg:[    0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
> dmesg-[    0.781707] ata2: port disabled--ignoring
> --
> dmesg.0:[    0.948881] ata_piix 0000:00:1f.2: MAP [
> dmesg.0-[    0.948883]  P0 P2 P1 P3 ]
>
> These messages originate starting at
> drivers/ata/ata_piix.c:1354
>
> All the continuations are emitted with pr_cont.
>
> I think this output should still be coalesced without
> timestamp deltas.  Perhaps the timestamping code can
> still be reworked to avoid too small a delta producing
> a new timestamp and another dmesg line.

Hmm, I don't see that.

If I do:
  pr_info("[");
  for (i = 0; i < 4; i++)
       pr_cont("%i ", i);
  pr_cont("]\n");

I get:
  6,173,0;[0 1 2 3 ]

And if I fill the cont buffer and forcefully hold the console sem
during all that, and we can't merge anymore, I get:
  6,167,0;[
  4,168,0;0
  4,169,0;1
  4,170,0;2
  4,171,0;3
  4,172,0;]

But the output is still all fine for both lines:
  [    0.000000] [0 1 2 3 ]
  [    0.000000] [0 1 2 3 ]

What do I miss?

Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Joe Perches]

On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote:
> On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <joe@perches.com> wrote:
> > On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote:
> >
> >> At the same time the CPU#2 prints the same warning with a continuation
> >> line, but the buffer from CPU#1 can not be flushed to the console, nor
> >> can the continuation line printk()s from CPU#2 be merged at this point.
> >> The consoles are still locked and busy with replaying the old log
> >> messages, so the new continuation data is just stored away in the record
> >> buffer as it is coming in.
> >> If the console would be registered a bit earlier, or the warning would
> >> happen a bit later, we would probably not see any of this.
> >>
> >> I can fake something like this just by holding the console semaphore
> >> over a longer time and printing continuation lines with different CPUs
> >> in a row.
> >>
> >> The patch below seems to work for me. It is also here:
> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
> >>
> >> It only applies cleanly on top of this patch:
> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
> >>
> >
> > Hi Kay.
> >
> > I just ran a test with what's in Greg's driver-core -for-linus branch.
> >
> > One of the differences in dmesg is timestamping of consecutive
> >         pr_<level>("foo...)
> > followed directly by
> >         pr_cont("bar...")
> >
> > For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+)
> >
> > # grep MAP /var/log/dm* -A1
> > dmesg:[    0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
> > dmesg-[    0.781707] ata2: port disabled--ignoring
> > --
> > dmesg.0:[    0.948881] ata_piix 0000:00:1f.2: MAP [
> > dmesg.0-[    0.948883]  P0 P2 P1 P3 ]
> >
> > These messages originate starting at
> > drivers/ata/ata_piix.c:1354
> >
> > All the continuations are emitted with pr_cont.
> >
> > I think this output should still be coalesced without
> > timestamp deltas.  Perhaps the timestamping code can
> > still be reworked to avoid too small a delta producing
> > a new timestamp and another dmesg line.
> 
> Hmm, I don't see that.
> 
> If I do:
>   pr_info("[");
>   for (i = 0; i < 4; i++)
>        pr_cont("%i ", i);
>   pr_cont("]\n");
> 
> I get:
>   6,173,0;[0 1 2 3 ]
> 
> And if I fill the cont buffer and forcefully hold the console sem
> during all that, and we can't merge anymore, I get:
>   6,167,0;[
>   4,168,0;0
>   4,169,0;1
>   4,170,0;2
>   4,171,0;3
>   4,172,0;]
> 
> But the output is still all fine for both lines:
>   [    0.000000] [0 1 2 3 ]
>   [    0.000000] [0 1 2 3 ]
> 
> What do I miss?

In this case the initial line is dev_info not pr_info
so there are the additional dict descriptors output to
/dev/kmsg as well.

Maybe that interferes with continuations.  Dunno.

Re: [PATCH v3] printk: Have printk() never buffer its data

[Kay Sievers]

On Tue, Jul 10, 2012 at 12:29 AM, Joe Perches <joe@perches.com> wrote:
> On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote:
>> On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <joe@perches.com> wrote:
>> > On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote:
>> >
>> >> At the same time the CPU#2 prints the same warning with a continuation
>> >> line, but the buffer from CPU#1 can not be flushed to the console, nor
>> >> can the continuation line printk()s from CPU#2 be merged at this point.
>> >> The consoles are still locked and busy with replaying the old log
>> >> messages, so the new continuation data is just stored away in the record
>> >> buffer as it is coming in.
>> >> If the console would be registered a bit earlier, or the warning would
>> >> happen a bit later, we would probably not see any of this.
>> >>
>> >> I can fake something like this just by holding the console semaphore
>> >> over a longer time and printing continuation lines with different CPUs
>> >> in a row.
>> >>
>> >> The patch below seems to work for me. It is also here:
>> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
>> >>
>> >> It only applies cleanly on top of this patch:
>> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
>> >>
>> >
>> > Hi Kay.
>> >
>> > I just ran a test with what's in Greg's driver-core -for-linus branch.
>> >
>> > One of the differences in dmesg is timestamping of consecutive
>> >         pr_<level>("foo...)
>> > followed directly by
>> >         pr_cont("bar...")
>> >
>> > For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+)
>> >
>> > # grep MAP /var/log/dm* -A1
>> > dmesg:[    0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
>> > dmesg-[    0.781707] ata2: port disabled--ignoring
>> > --
>> > dmesg.0:[    0.948881] ata_piix 0000:00:1f.2: MAP [
>> > dmesg.0-[    0.948883]  P0 P2 P1 P3 ]
>> >
>> > These messages originate starting at
>> > drivers/ata/ata_piix.c:1354
>> >
>> > All the continuations are emitted with pr_cont.
>> >
>> > I think this output should still be coalesced without
>> > timestamp deltas.  Perhaps the timestamping code can
>> > still be reworked to avoid too small a delta producing
>> > a new timestamp and another dmesg line.
>>
>> Hmm, I don't see that.
>>
>> If I do:
>>   pr_info("[");
>>   for (i = 0; i < 4; i++)
>>        pr_cont("%i ", i);
>>   pr_cont("]\n");
>>
>> I get:
>>   6,173,0;[0 1 2 3 ]
>>
>> And if I fill the cont buffer and forcefully hold the console sem
>> during all that, and we can't merge anymore, I get:
>>   6,167,0;[
>>   4,168,0;0
>>   4,169,0;1
>>   4,170,0;2
>>   4,171,0;3
>>   4,172,0;]
>>
>> But the output is still all fine for both lines:
>>   [    0.000000] [0 1 2 3 ]
>>   [    0.000000] [0 1 2 3 ]
>>
>> What do I miss?
>
> In this case the initial line is dev_info not pr_info
> so there are the additional dict descriptors output to
> /dev/kmsg as well.
>
> Maybe that interferes with continuations.  Dunno.

Yes, it does. Annotated records dev_printk() must be reliable in the
data storage and for the consumers. We can not expose them to the racy
continuation printk()s. We need to be able to trust the data they
print and not possibly merge unrelated things into it.

If it's needed, we can try to set the flags accordingly, that they
*look* like a line in the classic byte-stream output, but the
interface in /dev/kmsg must not export them that way, because
continuation lines can never be trusted to be correct.

Kay

Re: [PATCH v3] printk: Have printk() never buffer its data

[Joe Perches]

On Tue, 2012-07-10 at 00:40 +0200, Kay Sievers wrote:
> On Tue, Jul 10, 2012 at 12:29 AM, Joe Perches <joe@perches.com> wrote:
> > On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote:
> >> On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <joe@perches.com> wrote:
> >> > On Sun, 2012-07-08 at 19:55 +0200, Kay Sievers wrote:
> >> >
> >> >> At the same time the CPU#2 prints the same warning with a continuation
> >> >> line, but the buffer from CPU#1 can not be flushed to the console, nor
> >> >> can the continuation line printk()s from CPU#2 be merged at this point.
> >> >> The consoles are still locked and busy with replaying the old log
> >> >> messages, so the new continuation data is just stored away in the record
> >> >> buffer as it is coming in.
> >> >> If the console would be registered a bit earlier, or the warning would
> >> >> happen a bit later, we would probably not see any of this.
> >> >>
> >> >> I can fake something like this just by holding the console semaphore
> >> >> over a longer time and printing continuation lines with different CPUs
> >> >> in a row.
> >> >>
> >> >> The patch below seems to work for me. It is also here:
> >> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-merge-cont.patch;hb=HEAD
> >> >>
> >> >> It only applies cleanly on top of this patch:
> >> >>   http://git.kernel.org/?p=linux/kernel/git/kay/patches.git;a=blob;f=kmsg-syslog-1-byte-read.patch;hb=HEAD
> >> >>
> >> >
> >> > Hi Kay.
> >> >
> >> > I just ran a test with what's in Greg's driver-core -for-linus branch.
> >> >
> >> > One of the differences in dmesg is timestamping of consecutive
> >> >         pr_<level>("foo...)
> >> > followed directly by
> >> >         pr_cont("bar...")
> >> >
> >> > For instance: (dmesg is 3.4, dmesg.0 is 3.5-rc6+)
> >> >
> >> > # grep MAP /var/log/dm* -A1
> >> > dmesg:[    0.781687] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
> >> > dmesg-[    0.781707] ata2: port disabled--ignoring
> >> > --
> >> > dmesg.0:[    0.948881] ata_piix 0000:00:1f.2: MAP [
> >> > dmesg.0-[    0.948883]  P0 P2 P1 P3 ]
> >> >
> >> > These messages originate starting at
> >> > drivers/ata/ata_piix.c:1354
> >> >
> >> > All the continuations are emitted with pr_cont.
> >> >
> >> > I think this output should still be coalesced without
> >> > timestamp deltas.  Perhaps the timestamping code can
> >> > still be reworked to avoid too small a delta producing
> >> > a new timestamp and another dmesg line.
> >>
> >> Hmm, I don't see that.
> >>
> >> If I do:
> >>   pr_info("[");
> >>   for (i = 0; i < 4; i++)
> >>        pr_cont("%i ", i);
> >>   pr_cont("]\n");
> >>
> >> I get:
> >>   6,173,0;[0 1 2 3 ]
> >>
> >> And if I fill the cont buffer and forcefully hold the console sem
> >> during all that, and we can't merge anymore, I get:
> >>   6,167,0;[
> >>   4,168,0;0
> >>   4,169,0;1
> >>   4,170,0;2
> >>   4,171,0;3
> >>   4,172,0;]
> >>
> >> But the output is still all fine for both lines:
> >>   [    0.000000] [0 1 2 3 ]
> >>   [    0.000000] [0 1 2 3 ]
> >>
> >> What do I miss?
> >
> > In this case the initial line is dev_info not pr_info
> > so there are the additional dict descriptors output to
> > /dev/kmsg as well.
> >
> > Maybe that interferes with continuations.  Dunno.
> 
> Yes, it does. Annotated records dev_printk() must be reliable in the
> data storage and for the consumers. We can not expose them to the racy
> continuation printk()s. We need to be able to trust the data they
> print and not possibly merge unrelated things into it.
> 
> If it's needed, we can try to set the flags accordingly, that they
> *look* like a line in the classic byte-stream output, but the
> interface in /dev/kmsg must not export them that way, because
> continuation lines can never be trusted to be correct.

Then you've changed semantics and I think you need to
fix it.

A dev_<level> call is not guaranteed to be a complete
message.

There are dev_<level> and netdev_<level> calls
followed by pr_cont.

Maybe these could be fixed up and then they could be
always integral.  There don't look to be too many.

This may be most (all?) of them:

 drivers/ata/ata_piix.c               |   16 +++++++++-----
 drivers/media/rc/redrat3.c           |   36 ++++++++++++++++-----------------
 drivers/net/ethernet/broadcom/bnx2.c |   26 ++++++++++++++----------
 3 files changed, 42 insertions(+), 36 deletions(-)

diff --git a/drivers/ata/ata_piix.c b/drivers/ata/ata_piix.c
index 3c809bf..f51962f 100644
--- a/drivers/ata/ata_piix.c
+++ b/drivers/ata/ata_piix.c
@@ -1346,38 +1346,42 @@ static const int *__devinit piix_init_sata_map(struct pci_dev *pdev,
 	const int *map;
 	int i, invalid_map = 0;
 	u8 map_value;
+	char maps[50] = {0};
+	int len = 0;
 
 	pci_read_config_byte(pdev, ICH5_PMR, &map_value);
 
 	map = map_db->map[map_value & map_db->mask];
 
-	dev_info(&pdev->dev, "MAP [");
 	for (i = 0; i < 4; i++) {
 		switch (map[i]) {
 		case RV:
 			invalid_map = 1;
-			pr_cont(" XX");
+			len += snprintf(maps + len, sizeof(maps) - len, " XX");
 			break;
 
 		case NA:
-			pr_cont(" --");
+			len += snprintf(maps + len, sizeof(maps) - len, " --");
 			break;
 
 		case IDE:
 			WARN_ON((i & 1) || map[i + 1] != IDE);
 			pinfo[i / 2] = piix_port_info[ich_pata_100];
 			i++;
-			pr_cont(" IDE IDE");
+			len += snprintf(maps + len, sizeof(maps) - len,
+					" IDE IDE");
 			break;
 
 		default:
-			pr_cont(" P%d", map[i]);
+			len += snprintf(maps + len, sizeof(maps) - len,
+					" P%d", map[i]);
 			if (i & 1)
 				pinfo[i / 2].flags |= ATA_FLAG_SLAVE_POSS;
 			break;
 		}
 	}
-	pr_cont(" ]\n");
+
+	dev_info(&pdev->dev, "MAP [%s ]\n", maps);
 
 	if (invalid_map)
 		dev_err(&pdev->dev, "invalid MAP value %u\n", map_value);
diff --git a/drivers/media/rc/redrat3.c b/drivers/media/rc/redrat3.c
index 2878b0e..636a245 100644
--- a/drivers/media/rc/redrat3.c
+++ b/drivers/media/rc/redrat3.c
@@ -296,41 +296,36 @@ static void redrat3_issue_async(struct redrat3_dev *rr3)
 
 static void redrat3_dump_fw_error(struct redrat3_dev *rr3, int code)
 {
-	if (!rr3->transmitting && (code != 0x40))
-		dev_info(rr3->dev, "fw error code 0x%02x: ", code);
+	const char *msg = "";
 
 	switch (code) {
 	case 0x00:
-		pr_cont("No Error\n");
+		msg = "No Error";
 		break;
 
 	/* Codes 0x20 through 0x2f are IR Firmware Errors */
 	case 0x20:
-		pr_cont("Initial signal pulse not long enough "
-			"to measure carrier frequency\n");
+		msg = "Initial signal pulse not long enough to measure carrier frequency";
 		break;
 	case 0x21:
-		pr_cont("Not enough length values allocated for signal\n");
+		msg = "Not enough length values allocated for signal";
 		break;
 	case 0x22:
-		pr_cont("Not enough memory allocated for signal data\n");
+		msg = "Not enough memory allocated for signal data";
 		break;
 	case 0x23:
-		pr_cont("Too many signal repeats\n");
+		msg = "Too many signal repeats";
 		break;
 	case 0x28:
-		pr_cont("Insufficient memory available for IR signal "
-			"data memory allocation\n");
+		msg = "Insufficient memory available for IR signal data memory allocation";
 		break;
 	case 0x29:
-		pr_cont("Insufficient memory available "
-			"for IrDa signal data memory allocation\n");
+		msg = "Insufficient memory available for IrDa signal data memory allocation";
 		break;
 
 	/* Codes 0x30 through 0x3f are USB Firmware Errors */
 	case 0x30:
-		pr_cont("Insufficient memory available for bulk "
-			"transfer structure\n");
+		msg = "Insufficient memory available for bulk transfer structure";
 		break;
 
 	/*
@@ -339,20 +334,23 @@ static void redrat3_dump_fw_error(struct redrat3_dev *rr3, int code)
 	 */
 	case 0x40:
 		if (!rr3->transmitting)
-			pr_cont("Signal capture has been terminated\n");
+			msg = "Signal capture has been terminated";
 		break;
 	case 0x41:
-		pr_cont("Attempt to set/get and unknown signal I/O "
-			"algorithm parameter\n");
+		msg = "Attempt to set/get and unknown signal I/O algorithm parameter";
 		break;
 	case 0x42:
-		pr_cont("Signal capture already started\n");
+		msg = "Signal capture already started";
 		break;
 
 	default:
-		pr_cont("Unknown Error\n");
+		msg = "Unknown Error";
 		break;
 	}
+
+	if (!rr3->transmitting && (code != 0x40))
+		dev_info(rr3->dev, "fw error code 0x%02x: %s\n", code, msg);
+
 }
 
 static u32 redrat3_val_to_mod_freq(struct redrat3_signal_header *ph)
diff --git a/drivers/net/ethernet/broadcom/bnx2.c b/drivers/net/ethernet/broadcom/bnx2.c
index 1901da1..f5dd19f 100644
--- a/drivers/net/ethernet/broadcom/bnx2.c
+++ b/drivers/net/ethernet/broadcom/bnx2.c
@@ -987,24 +987,28 @@ static void
 bnx2_report_link(struct bnx2 *bp)
 {
 	if (bp->link_up) {
+		const char *fc_type = "";
+		const char *fc_on = "";
 		netif_carrier_on(bp->dev);
-		netdev_info(bp->dev, "NIC %s Link is Up, %d Mbps %s duplex",
-			    bnx2_xceiver_str(bp),
-			    bp->line_speed,
-			    bp->duplex == DUPLEX_FULL ? "full" : "half");
 
 		if (bp->flow_ctrl) {
 			if (bp->flow_ctrl & FLOW_CTRL_RX) {
-				pr_cont(", receive ");
 				if (bp->flow_ctrl & FLOW_CTRL_TX)
-					pr_cont("& transmit ");
-			}
-			else {
-				pr_cont(", transmit ");
+					fc_type = ", receive & transmit";
+				else
+					fc_type = ", receive";
+
+			} else {
+				fc_type = ", transmit";
 			}
-			pr_cont("flow control ON");
+			fc_on = " flow control ON";
 		}
-		pr_cont("\n");
+		netdev_info(bp->dev, "NIC %s Link is Up, %d Mbps %s duplex%s%s\n",
+			    bnx2_xceiver_str(bp),
+			    bp->line_speed,
+			    bp->duplex == DUPLEX_FULL ? "full" : "half",
+			    fc_type, fc_on);
+
 	} else {
 		netif_carrier_off(bp->dev);
 		netdev_err(bp->dev, "NIC %s Link is Down\n",

Re: [PATCH v3] printk: Have printk() never buffer its data

[Joe Perches]

On Mon, 2012-07-09 at 16:32 -0700, Joe Perches wrote:
> Then you've changed semantics and I think you need to
> fix it.
> 
> A dev_<level> call is not guaranteed to be a complete
> message.
> 
> There are dev_<level> and netdev_<level> calls
> followed by pr_cont.
> 
> Maybe these could be fixed up and then they could be
> always integral.  There don't look to be too many.
> 
> This may be most (all?) of them:

Nah, there's a bunch more:

$ git grep -E -A10 "\b(netdev|dev)_(info|warn|notice|err|alert|emerg|crit)" drivers | \
  grep -B10 -E "\bprintk\s*\(\s*(KERN_CONT|)\s*\""

All of them could be fixed up though.