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

[Kay Sievers]

On Tue, Jul 10, 2012 at 12:29 AM, Joe Perches <joe at perches.com> wrote:
> On Tue, 2012-07-10 at 00:10 +0200, Kay Sievers wrote:
>> On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <joe at perches.com> wrote:
>> > 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.
>>
>> 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