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

[Joe Perches <joe@perches.com>]

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