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

From: Kay Sievers <kay@vrfy.org>
To: Michael Neuling <mikey@neuling.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, 6 Jul 2012 17:12:12 +0200	[thread overview]
Message-ID: <CAPXgP10JthGjZyqD6gqn2n1rPu1uP+=mem_T-iOritXAQMstRQ@mail.gmail.com> (raw)
In-Reply-To: <CAPXgP13_cQUQLE4RSjACTzj28Pn6r3ZaPhjch2U+uwgi7YKcWA@mail.gmail.com>

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