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

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:

quoted

Whole kmsg below.

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

quoted

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.

quoted

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.

quoted

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