Re: [PATCH] printk: drop ambiguous LOG_CONT flag
From: "Jan H. SchÃnherr"
Date: Thu Sep 27 2012 - 11:46:44 EST
Am 27.09.2012 15:39, schrieb Kay Sievers:
> On Thu, Sep 27, 2012 at 12:33 AM, "Jan H. SchÃnherr"
> <schnhrr@xxxxxxxxxxxxxxx> wrote:
>> "Tested" as in: it fixes my use case: multiple printk()s shortly after each
>> other -- with KERN_prefix but without a newline at the end. Those were
>> sometimes concatenated since that printk-rewrite.
>
> Please provide the output of /dev/kmsg so we can see what's going on here.
Here we go. Test case attached. (Now I would say, the patch is
lightly to moderately tested.)
======= Results with v3.6-rc7 without patch =========
virtual-parasit ~ # insmod foo.ko; rmmod foo
[ 122.965207] newline 1
[ 122.965583] newline 2newline 3
[ 122.965904] newline 4newline 5
[ 122.966221] newline 6newline 7
[ 122.966681] newline 8newline 9
[ 122.966978] newline 10 continued 1 continued 2 continued 3
[ 122.966980] newline 11 continued 4 continued 5 continued 6 continued 7
[ 122.966980] newline 12
[ 122.966981] newline 13
[ 122.966981] newline 15
[ 122.966983] newline 16a
[ 122.966983] newline 16b
[ 122.966983] newline 16c continued 8
[ 122.966983] newline 17
[ 122.966983] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # insmod foo.ko; rmmod foo
[ 128.993048] newline 1newline 2
[ 128.993414] newline 3newline 4
[ 128.993776] newline 5newline 6
[ 128.994009] newline 7
[ 128.994010] newline 8
[ 128.994010] newline 9
[ 128.994011] newline 10 continued 1 continued 2 continued 3
[ 128.994012] newline 11 continued 4 continued 5 continued 6 continued 7
[ 128.994013] newline 12
[ 128.994013] newline 13
[ 128.994013] newline 15
[ 128.994020] newline 16a
[ 128.994020] newline 16b
[ 128.994020] newline 16c continued 8
[ 128.994020] newline 17
[ 128.994020] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # cat /dev/kmsg
<snip>
7,397,122965207,-;newline 1
7,398,122965583,c;newline 2
7,399,122965820,+;newline 3
7,400,122965904,c;newline 4
7,401,122966136,+;newline 5
7,402,122966221,c;newline 6
6,403,122966532,+;newline 7
7,404,122966681,c;newline 8
6,405,122966977,+;newline 9
7,406,122966978,-;newline 10 continued 1 continued 2 continued 3
7,407,122966980,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,408,122966980,-;newline 12
4,409,122966981,-;newline 13
4,410,122966981,-;newline 15
7,411,122966983,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
7,412,122966983,-;newline 18a\x0anewline 18b\x0anewline 18c continued 9
7,413,128993048,c;newline 1
7,414,128993318,+;newline 2
7,415,128993414,c;newline 3
7,416,128993691,+;newline 4
7,417,128993776,c;newline 5
7,418,128994009,+;newline 6
6,419,128994009,-;newline 7
7,420,128994010,-;newline 8
6,421,128994010,-;newline 9
7,422,128994011,-;newline 10 continued 1 continued 2 continued 3
7,423,128994012,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,424,128994013,-;newline 12
4,425,128994013,-;newline 13
4,426,128994013,-;newline 15
7,427,128994020,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
=====================================================
Without the patch results are pretty non-deterministic.
Sometimes also concatenating timestamps, e. g.:
virtual-parasit ~ # insmod foo.ko; rmmod foo
[ 29.624176] newline 1newline 2
[ 29.624589] newline 3newline 4
[ 29.625155] newline 5newline 6
[ 29.625572] newline 7newline 8newline 9newline 10 continued 1 continued 2 continued 3newline 11
continued 4 continued 5 continued 6 continued 7[ 29.625575] newline 12
[ 29.625576] newline 13
[ 29.625576] newline 15
[ 29.625576] newline 16a
[ 29.625576] newline 16b
[ 29.625576] newline 16c continued 8
[ 29.625577] newline 17newline 18a
[ 29.625577] newline 18b
[ 29.625577] newline 18c continued 9
7,604,29624176,c;newline 1
7,605,29624449,+;newline 2
7,606,29624589,c;newline 3
7,607,29625051,+;newline 4
7,608,29625155,c;newline 5
7,609,29625479,+;newline 6
6,610,29625572,c;newline 7
7,611,29625572,+;newline 8
6,612,29625572,+;newline 9
7,613,29625573,+;newline 10
4,614,29625573,+; continued 1
4,615,29625573,+; continued 2
4,616,29625574,+; continued 3
7,617,29625574,+;newline 11
4,618,29625574,+; continued 4
4,619,29625574,+; continued 5
4,620,29625575,+; continued 6
4,621,29625575,+; continued 7
6,622,29625575,-;newline 12
4,623,29625576,-;newline 13
4,624,29625576,-;newline 15
7,625,29625576,c;newline 16a\x0anewline 16b\x0anewline 16c
4,626,29625577,+; continued 8\x0anewline 17
7,627,29625577,+;newline 18a\x0anewline 18b\x0anewline 18c
4,628,29625577,+; continued 9
dmesg for this one:
[ 29.624176] newline 1newline 2
[ 29.624589] newline 3newline 4
[ 29.625155] newline 5newline 6
[ 29.625572] newline 7newline 8newline 9newline 10 continued 1 continued 2 continued 3newline 11
continued 4 continued 5 continued 6 continued 7<6>[ 29.625575] newline 12
[ 29.625576] newline 13
[ 29.625576] newline 15
[ 29.625576] newline 16a
[ 29.625576] newline 16b
[ 29.625576] newline 16c continued 8
[ 29.625577] newline 17newline 18a
[ 29.625577] newline 18b
[ 29.625577] newline 18c continued 9newline 1
======= Results with v3.6-rc7 with patch ============
virtual-parasit ~ # insmod foo.ko; rmmod foo
[ 47.619453] newline 1
[ 47.619719] newline 2
[ 47.619974] newline 3
[ 47.620182] newline 4
[ 47.620474] newline 5
[ 47.620763] newline 6
[ 47.621007] newline 7
[ 47.621008] newline 8
[ 47.621008] newline 9
[ 47.621009] newline 10 continued 1 continued 2 continued 3
[ 47.621011] newline 11 continued 4 continued 5 continued 6 continued 7
[ 47.621011] newline 12
[ 47.621011] newline 13
[ 47.621011] newline 15
[ 47.621012] newline 16a
[ 47.621012] newline 16b
[ 47.621012] newline 16c continued 8
[ 47.621012] newline 17
[ 47.621012] newline 18a
newline 18b
newline 18c continued 9virtual-parasit ~ # insmod foo.ko; rmmod foo
[ 49.979192] newline 1
[ 49.979630] newline 2
[ 49.979876] newline 3
[ 49.979876] newline 4
[ 49.979877] newline 5
[ 49.979877] newline 6
[ 49.979877] newline 7
[ 49.979878] newline 8
[ 49.979878] newline 9
[ 49.979878] newline 10 continued 1 continued 2 continued 3
[ 49.979879] newline 11 continued 4 continued 5 continued 6 continued 7
[ 49.979885] newline 12
[ 49.979895] newline 13
[ 49.979896] newline 15
[ 49.979896] newline 16a
[ 49.979896] newline 16b
[ 49.979896] newline 16c continued 8
[ 49.979897] newline 17
[ 49.979897] newline 18a
[ 49.979897] newline 18b
[ 49.979897] newline 18c continued 9virtual-parasit ~ # cat /dev/kmsg
<snip>
7,397,47619453,-;newline 1
7,398,47619719,c;newline 2
7,399,47619974,-;newline 3
7,400,47620182,c;newline 4
7,401,47620474,-;newline 5
7,402,47620763,c;newline 6
6,403,47621007,-;newline 7
7,404,47621008,-;newline 8
6,405,47621008,-;newline 9
7,406,47621009,-;newline 10 continued 1 continued 2 continued 3
7,407,47621011,-;newline 11 continued 4 continued 5 continued 6 continued 7
6,408,47621011,-;newline 12
4,409,47621011,-;newline 13
4,410,47621011,-;newline 15
7,411,47621012,-;newline 16a\x0anewline 16b\x0anewline 16c continued 8\x0anewline 17
7,412,47621012,-;newline 18a\x0anewline 18b\x0anewline 18c continued 9
7,413,49979192,c;newline 1
7,414,49979630,-;newline 2
7,415,49979876,c;newline 3
7,416,49979876,c;newline 4
7,417,49979877,c;newline 5
7,418,49979877,c;newline 6
6,419,49979877,c;newline 7
7,420,49979878,c;newline 8
6,421,49979878,c;newline 9
7,422,49979878,c;newline 10
4,423,49979879,+; continued 1
4,424,49979879,+; continued 2
4,425,49979879,+; continued 3
7,426,49979879,c;newline 11
4,427,49979880,+; continued 4
4,428,49979880,+; continued 5
4,429,49979880,+; continued 6
4,430,49979880,+; continued 7
6,431,49979885,-;newline 12
4,432,49979895,-;newline 13
4,433,49979896,-;newline 15
7,434,49979896,c;newline 16a\x0anewline 16b\x0anewline 16c
4,435,49979897,+; continued 8\x0anewline 17
7,436,49979897,c;newline 18a\x0anewline 18b\x0anewline 18c
4,437,49979897,+; continued 9
>> I was also hoping that Kay might share his opinion, as the LOG_CONT
>> flag is rather young, and he might have some different plans for it.
>
> It is a flag that we have not been able to merge a continuation line
> in the buffer, because we had a race with another thread, or the
> console lock was taken for a long time and we couldn't use the merge
> buffer.
But it is also set, if we don't know yet, whether there is going to
be a continuation (printk.c, line 1583):
log_store(facility, level, lflags | LOG_CONT, 0,
dict, dictlen, text, text_len);
This confuses devkmsg_read() and msg_print_text() later on.
> LOG_CONT is used to merge (not intended to be) separate records at
> time we read them from the record buffer, and print them, it is also
> exported as a flag in /dev/kmsg.
>
> I don't think we can just remove it, we can not get that information
> from the prefix+newlines, they are not sufficient.
Here I disagree. ;)
If we say "if LOG_CONT is set, next message might be a continuation",
then that is similar to saying "there is no newline at the end of this
message". And we would need an additional flag on messages indicating
that a message does not continue a previous message.
If we say "if LOG_CONT is set, this message continues the previous one",
we can also say "there is no prefix on this message". Then on the other
hand, we would need a "whatever comes next, it does not continue this
message"....
However, if you want to be able to fully sort out continuation line races
afterwards and be able to reconstruct a race free output, then I agree
that the current information is not sufficient.
Regards
Jan
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/init.h>
static int __init foo_init(void)
{
printk(KERN_DEBUG "newline 1");
printk(KERN_DEBUG "newline 2");
printk(KERN_DEBUG "newline 3");
printk(KERN_DEBUG "newline 4");
printk(KERN_DEBUG "newline 5");
printk(KERN_DEBUG "newline 6");
printk(KERN_INFO "newline 7");
printk(KERN_DEBUG "newline 8");
printk(KERN_INFO "newline 9");
printk(KERN_DEBUG "newline 10");
printk(KERN_CONT " continued 1");
printk(KERN_CONT " continued 2");
printk(KERN_CONT " continued 3");
printk(KERN_DEBUG "newline 11");
printk(KERN_CONT " continued 4");
printk( " continued 5");
printk( " continued 6");
printk( " continued 7");
printk(KERN_INFO "newline 12\n");
printk(KERN_CONT "newline 13\n");
printk(KERN_CONT "newline 15\n");
printk(KERN_DEBUG "newline 16a\nnewline 16b\nnewline 16c");
printk( " continued 8\nnewline 17");
printk(KERN_DEBUG "newline 18a\nnewline 18b\nnewline 18c");
printk( " continued 9");
return 0;
}
static void __exit foo_exit(void)
{
}
module_init(foo_init);
module_exit(foo_exit);
MODULE_LICENSE("GPL");