[RFC/PATCH] printk: detect incomplete lines - Kernel

This is a discussion on [RFC/PATCH] printk: detect incomplete lines - Kernel ; Hi, This printk() problem has been bugging me for a long time. Consider the following code: diff --git a/init/main.c b/init/main.c index ddada7a..777e02d 100644 --- a/init/main.c +++ b/init/main.c @@ -452,17 +452,38 @@ static void __init setup_command_line(char *command_line) * gcc-3.4 accidentally inlines ...

+ Reply to Thread
Results 1 to 6 of 6

Thread: [RFC/PATCH] printk: detect incomplete lines

  1. [RFC/PATCH] printk: detect incomplete lines

    Hi,

    This printk() problem has been bugging me for a long time. Consider the
    following code:

    diff --git a/init/main.c b/init/main.c
    index ddada7a..777e02d 100644
    --- a/init/main.c
    +++ b/init/main.c
    @@ -452,17 +452,38 @@ static void __init setup_command_line(char *command_line)
    * gcc-3.4 accidentally inlines this function, so use noinline.
    */

    +static void printk_thread(const char *msg, unsigned long wait)
    +{
    + int i = 0;
    +
    + while(true) {
    + if (i == 0)
    + printk(KERN_INFO "Here we go: ");
    +
    + printk("%s%s", msg, i < 7 ? ", " : "\n");
    + if (++i == 8)
    + i = 0;
    + msleep(wait);
    + }
    +}
    +
    +static void printk_thread_1(void) { printk_thread("thread 1", 30); }
    +static void printk_thread_2(void) { printk_thread("thread 2", 20); }
    +
    static void noinline __init_refok rest_init(void)
    __releases(kernel_lock)
    {
    int pid;

    - kernel_thread(kernel_init, NULL, CLONE_FS | CLONE_SIGHAND);
    + //kernel_thread(kernel_init, NULL, CLONE_FS | CLONE_SIGHAND);
    numa_default_policy();
    pid = kernel_thread(kthreadd, NULL, CLONE_FS | CLONE_FILES);
    kthreadd_task = find_task_by_pid_ns(pid, &init_pid_ns);
    unlock_kernel();

    + kernel_thread(printk_thread_1, NULL, CLONE_FS | CLONE_SIGHAND);
    + kernel_thread(printk_thread_2, NULL, CLONE_FS | CLONE_SIGHAND);
    +
    /*
    * The boot idle thread must execute schedule()
    * at least once to get things moving:

    This will normally create an output that looks something like this:

    Here we go: thread 2, <6>Here we go: thread 1, thread 2, thread 1, thread 2, thread 1, thread 2, thread 2, thread 1, thread 2, thread 1, thread 2, thread 2
    thread 1, <6>Here we go: thread 2, thread 1, thread 2, thread 2, thread 1
    thread 2, <6>Here we go: thread 1, thread 2, thread 2, thread 1, thread 2, thread 1, thread 2

    (Notice the log-level tokens appearing in the middle of some lines.)

    With my patch to printk(), the same code now produces this output:

    Here we go: thread 1, ...
    Here we go: thread 2, thread 2, ...
    thread 1, ...
    thread 2, ...
    thread 1, ...
    thread 2, thread 2, ...
    thread 1, ...

    I first thought of using "current" as the way to distinguish two callers,
    but there are two issues with this: 1) I don't think "current" is legal to
    access in all contexts, but maybe I am wrong. 2) Executing some kernel
    code, say a system call, and an IRQ happening while we are executing inside
    that system call will not make "current" change.

    Then I thought of using __builtin_return_address(), but in a function, two
    different printks will have a different return address.

    So we are now using __builtin_frame_address(). This should work everywhere
    and should not cause any harmful side effects.

    (Yes, this means that "continuation calls across functions" won't work. But
    that's broken by design, at least in my opinion.)

    The GCC manual says "This function should only be used with a nonzero
    argument for debugging purposes", but it is nothing to worry about, as we
    are in fact calling it with a zero argument.

    The only thing I worry about is whether it will work on all architectures.
    Does anybody see anything that can go wrong with this patch?

    (The remaining issue is to figure out what the loglevel of the next message
    should be, the one that is being continued. It may lead to "leaking" of
    certain loglevel messages, but that's a much more fundamental problem and
    this patch is at least a step in the right direction.)

    Vegard


    From 909874dbedd06271af5185f3eb5f710bb1267433 Mon Sep 17 00:00:00 2001
    From: Vegard Nossum
    Date: Mon, 12 May 2008 13:17:19 +0200
    Subject: [PATCH] printk: detect incomplete lines

    This patch makes printk() remember the previous caller, and if changed,
    output a newline to make the next message start in the right place.

    Signed-off-by: Vegard Nossum
    ---
    kernel/printk.c | 11 +++++++++++
    1 files changed, 11 insertions(+), 0 deletions(-)

    diff --git a/kernel/printk.c b/kernel/printk.c
    index 8fb01c3..6080e66 100644
    --- a/kernel/printk.c
    +++ b/kernel/printk.c
    @@ -672,6 +672,7 @@ static int printk_recursion_bug;

    asmlinkage int vprintk(const char *fmt, va_list args)
    {
    + static void *prev_caller;
    static int log_level_unknown = 1;
    static char printk_buf[1024];

    @@ -718,6 +719,16 @@ asmlinkage int vprintk(const char *fmt, va_list args)
    printed_len += vscnprintf(printk_buf + printed_len,
    sizeof(printk_buf) - printed_len, fmt, args);

    + if (prev_caller != __builtin_frame_address(0) && !log_level_unknown) {
    + emit_log_char('.');
    + emit_log_char('.');
    + emit_log_char('.');
    + emit_log_char('\n');
    + log_level_unknown = 1;
    + }
    +
    + prev_caller = __builtin_frame_address(0);
    +
    /*
    * Copy the output into log_buf. If the caller didn't provide
    * appropriate log level tags, we insert them here
    --
    1.5.4.1

    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  2. Re: [RFC/PATCH] printk: detect incomplete lines

    On Mon, May 12, 2008 at 2:49 PM, Vegard Nossum wrote:
    > This printk() problem has been bugging me for a long time. Consider the
    > following code:
    >
    > diff --git a/init/main.c b/init/main.c
    > index ddada7a..777e02d 100644
    > --- a/init/main.c
    > +++ b/init/main.c
    > @@ -452,17 +452,38 @@ static void __init setup_command_line(char *command_line)
    > * gcc-3.4 accidentally inlines this function, so use noinline.
    > */
    >
    > +static void printk_thread(const char *msg, unsigned long wait)
    > +{
    > + int i = 0;
    > +
    > + while(true) {
    > + if (i == 0)
    > + printk(KERN_INFO "Here we go: ");
    > +
    > + printk("%s%s", msg, i < 7 ? ", " : "\n");

    You are supposed to use KERN_CONT here.
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  3. Re: [RFC/PATCH] printk: detect incomplete lines

    On Mon, May 12, 2008 at 1:56 PM, Pekka Enberg wrote:
    > On Mon, May 12, 2008 at 2:49 PM, Vegard Nossum wrote:
    > > This printk() problem has been bugging me for a long time. Consider the
    > > following code:
    > >
    > > diff --git a/init/main.c b/init/main.c
    > > index ddada7a..777e02d 100644
    > > --- a/init/main.c
    > > +++ b/init/main.c
    > > @@ -452,17 +452,38 @@ static void __init setup_command_line(char *command_line)
    > > * gcc-3.4 accidentally inlines this function, so use noinline.
    > > */
    > >
    > > +static void printk_thread(const char *msg, unsigned long wait)
    > > +{
    > > + int i = 0;
    > > +
    > > + while(true) {
    > > + if (i == 0)
    > > + printk(KERN_INFO "Here we go: ");
    > > +
    > > + printk("%s%s", msg, i < 7 ? ", " : "\n");
    >
    > You are supposed to use KERN_CONT here.

    Uhm, no. KERN_CONT won't help at all, see include/linux/kernel.h:

    /*
    * Annotation for a "continued" line of log printout (only done after a
    * line that had no enclosing \n). Only to be used by core/arch code
    * during early bootup (a continued line is not SMP-safe otherwise).
    */
    #define KERN_CONT ""

    So even if I did, it would make no difference for the example :-)

    Iirc, KERN_CONT is mostly an annotation for the checkpatch script to
    suppress the warning about missing loglevel token.

    (And let's face it, there are places in the kernel that have continued
    lines even after early bootup.)

    Vegard

    --
    "The animistic metaphor of the bug that maliciously sneaked in while
    the programmer was not looking is intellectually dishonest as it
    disguises that the error is the programmer's own creation."
    -- E. W. Dijkstra, EWD1036
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  4. Re: [RFC/PATCH] printk: detect incomplete lines

    On Mon, 2008-05-12 at 13:49 +0200, Vegard Nossum wrote:
    > So we are now using __builtin_frame_address(). This should work everywhere
    > and should not cause any harmful side effects.

    Perhaps print an identifier using __builtin_frame_address(0)
    to allow an external tool to reassemble complete messages?

    > + if (prev_caller != __builtin_frame_address(0) && !log_level_unknown) {
    > + emit_log_char('.');
    > + emit_log_char('.');
    > + emit_log_char('.');
    > + emit_log_char('\n');
    > + log_level_unknown = 1;
    > + }
    > +
    > + prev_caller = __builtin_frame_address(0);
    > +

    maybe something like:

    static void emit_log_id(void *addr)
    {
    unsigned int i = 0;
    char id[sizeof(void *) * 2 + 6];
    sprintf(id, "{@%p}", addr);
    while (*id[i])
    emit_log_char(id[i++]);
    }
    ....
    caller = __builtin_frame_address(0);
    if (prev_caller != caller && !log_level_unknown) {
    emit_log_id(caller);
    log_level_unknown = 1;
    prev_caller = caller;
    }


    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  5. Re: [RFC/PATCH] printk: detect incomplete lines

    "Vegard Nossum" writes:
    >
    > Iirc, KERN_CONT is mostly an annotation for the checkpatch script to
    > suppress the warning about missing loglevel token.

    Perhaps it should be fixed to contain some magic token that is
    then detected by printk and handled appropiately? And then perhaps
    employee some kernel janitors to add it everywhere?

    I think that would be preferable over any heuristics as implemented
    in your original patch because there might be a legitimate need to
    get out non full line printks ASAP for debugging.

    -Andi
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

  6. Re: [RFC/PATCH] printk: detect incomplete lines

    On Tue, May 13, 2008 at 12:54 PM, Andi Kleen wrote:
    > "Vegard Nossum" writes:
    > >
    > > Iirc, KERN_CONT is mostly an annotation for the checkpatch script to
    > > suppress the warning about missing loglevel token.
    >
    > Perhaps it should be fixed to contain some magic token that is
    > then detected by printk and handled appropiately? And then perhaps
    > employee some kernel janitors to add it everywhere?
    >
    > I think that would be preferable over any heuristics as implemented
    > in your original patch because there might be a legitimate need to
    > get out non full line printks ASAP for debugging.

    I'm sorry, I don't understand what you mean. My original patch does
    not delay anything. My original patch simply inserts a newline before
    the next printk() if the caller is different and the current line is
    unterminated.

    What would be the purpose of the magic token? Please explain.


    Vegard

    --
    "The animistic metaphor of the bug that maliciously sneaked in while
    the programmer was not looking is intellectually dishonest as it
    disguises that the error is the programmer's own creation."
    -- E. W. Dijkstra, EWD1036
    --
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/
+ Reply to Thread
« [PATCH 1/1] [ASOC]: AD1980 audio codec ASOC driver | [RFC][PATCH 1/1] MAZE: Mazed processes monitor »