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

From: Michael Neuling <mikey@neuling.org>
To: Kay Sievers <kay@vrfy.org>
Cc: linuxppc-dev@ozlabs.org,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	Steven Rostedt <rostedt@goodmis.org>,
	LKML <linux-kernel@vger.kernel.org>, Ingo Molnar <mingo@elte.hu>,
	Wu Fengguang <fengguang.wu@intel.com>,
	Joe Perches <joe@perches.com>,
	"Paul E. McKenney" <paulmck@us.ibm.com>
Subject: Re: [PATCH v3] printk: Have printk() never buffer its data
Date: Fri, 06 Jul 2012 10:41:19 +1000	[thread overview]
Message-ID: <30233.1341535279@neuling.org> (raw)
In-Reply-To: <1341492628.834.3.camel@mop>

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;
>  		}
>  
> 