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

Joe Perches
2012-07-09T22:29:46Z

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