On Mon, Jul 9, 2012 at 11:42 PM, Joe Perches <j...@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? Kay -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majord...@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/