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

On Tue, Jul 10, 2012 at 12:29 AM, Joe Perches [off-list ref] wrote:

On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote:

quoted

On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches [off-list ref] wrote:

quoted

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

quoted

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