[PATCH] printk.caller - Kernel

This is a discussion on [PATCH] printk.caller - Kernel ; This adds the printk.caller=[0|1] boot parameter, default setting controlled by CONFIG_PRINTK_CALLER. (This is modelled on printk.time and CONFIG_PRINTK_TIME.) When this is set, each printk line is automagically prefixed with "{0x123abc} " giving the PC address of that printk call (actually ...

+ Reply to Thread
Results 1 to 4 of 4

Thread: [PATCH] printk.caller

  1. [PATCH] printk.caller

    This adds the printk.caller=[0|1] boot parameter, default setting
    controlled by CONFIG_PRINTK_CALLER. (This is modelled on printk.time
    and CONFIG_PRINTK_TIME.)

    When this is set, each printk line is automagically prefixed with
    "{0x123abc} " giving the PC address of that printk call (actually
    the PC address just after the call).

    As a kernel hacker, I always hate having to grep for some fragment
    of a message to find the code that generated it. But I always have
    my -g vmlinux handy, so:
    (gdb) info line *(0x123abc - 1)
    is real handy (it pops the source up in an Emacs buffer).

    Signed-off-by: Roland McGrath
    ---
    Documentation/kernel-parameters.txt | 3 ++
    include/linux/kernel.h | 4 ++-
    kernel/printk.c | 38 +++++++++++++++++++++++++++++-----
    lib/Kconfig.debug | 9 ++++++++
    4 files changed, 47 insertions(+), 7 deletions(-)

    diff --git a/Documentation/kernel-parameters.txt b/Documentation/kernel-parameters.txt
    index 1150444..9f1e1b9 100644
    --- a/Documentation/kernel-parameters.txt
    +++ b/Documentation/kernel-parameters.txt
    @@ -1689,6 +1689,9 @@ and is between 256 and 4096 characters. It is defined in the file
    printk.time= Show timing data prefixed to each printk message line
    Format: (1/Y/y=enable, 0/N/n=disable)

    + printk.caller= Show caller PC prefixed to each printk message line
    + Format: (1/Y/y=enable, 0/N/n=disable)
    +
    profile= [KNL] Enable kernel profiling via /proc/profile
    Format: [schedule,]
    Param: "schedule" - profile schedule points.
    diff --git a/include/linux/kernel.h b/include/linux/kernel.h
    index 2651f80..e03b475 100644
    --- a/include/linux/kernel.h
    +++ b/include/linux/kernel.h
    @@ -191,7 +191,9 @@ struct pid;
    extern struct pid *session_of_pgrp(struct pid *pgrp);

    #ifdef CONFIG_PRINTK
    -asmlinkage int vprintk(const char *fmt, va_list args)
    +# define vprintk(fmt, args) \
    + vprintk_caller(fmt, args, __builtin_return_address(0))
    +asmlinkage int vprintk_caller(const char *fmt, va_list args, void *caller)
    __attribute__ ((format (printf, 1, 0)));
    asmlinkage int printk(const char * fmt, ...)
    __attribute__ ((format (printf, 1, 2))) __cold;
    diff --git a/kernel/printk.c b/kernel/printk.c
    index b51b156..e4294c8 100644
    --- a/kernel/printk.c
    +++ b/kernel/printk.c
    @@ -532,6 +532,12 @@ static void emit_log_char(char c)
    logged_chars++;
    }

    +static void emit_log_chars(const char *p, unsigned n)
    +{
    + while (n-- > 0)
    + emit_log_char(*p++);
    +}
    +
    /*
    * Zap console related locks when oopsing. Only zap at most once
    * every 10 seconds, to leave time for slow consoles to print a
    @@ -560,6 +566,13 @@ static int printk_time = 0;
    #endif
    module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

    +#if defined(CONFIG_PRINTK_CALLER)
    +static int printk_caller = 1;
    +#else
    +static int printk_caller = 0;
    +#endif
    +module_param_named(caller, printk_caller, bool, S_IRUGO | S_IWUSR);
    +
    /* Check if we have any console registered that can be called early in boot. */
    static int have_callable_console(void)
    {
    @@ -662,7 +675,7 @@ static int recursion_bug;
    static int new_text_line = 1;
    static char printk_buf[1024];

    -asmlinkage int vprintk(const char *fmt, va_list args)
    +asmlinkage int vprintk_caller(const char *fmt, va_list args, void *caller)
    {
    int printed_len = 0;
    int current_log_level = default_message_loglevel;
    @@ -708,7 +721,6 @@ asmlinkage int vprintk(const char *fmt, va_list args)
    printed_len += vscnprintf(printk_buf + printed_len,
    sizeof(printk_buf) - printed_len, fmt, args);

    -
    /*
    * Copy the output into log_buf. If the caller didn't provide
    * appropriate log level tags, we insert them here
    @@ -732,7 +744,7 @@ asmlinkage int vprintk(const char *fmt, va_list args)

    if (printk_time) {
    /* Follow the token with the time */
    - char tbuf[50], *tp;
    + char tbuf[50];
    unsigned tlen;
    unsigned long long t;
    unsigned long nanosec_rem;
    @@ -743,11 +755,25 @@ asmlinkage int vprintk(const char *fmt, va_list args)
    (unsigned long) t,
    nanosec_rem / 1000);

    - for (tp = tbuf; tp < tbuf + tlen; tp++)
    - emit_log_char(*tp);
    + emit_log_chars(tbuf, tlen);
    printed_len += tlen;
    }

    + if (caller && printk_caller) {
    + char pbuf[sizeof caller * 2 + sizeof "{0x} "];
    + unsigned plen;
    +
    + if (sizeof caller > 4)
    + plen = sprintf(pbuf, "{0x%016lx} ",
    + (unsigned long) caller);
    + else
    + plen = sprintf(pbuf, "{0x%08lx} ",
    + (unsigned long) caller);
    +
    + emit_log_chars(pbuf, plen);
    + printed_len += plen;
    + }
    +
    if (!*p)
    break;
    }
    @@ -778,7 +804,7 @@ out_restore_irqs:
    return printed_len;
    }
    EXPORT_SYMBOL(printk);
    -EXPORT_SYMBOL(vprintk);
    +EXPORT_SYMBOL(vprintk_caller);

    #else

    diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
    index 0b50481..b90134e 100644
    --- a/lib/Kconfig.debug
    +++ b/lib/Kconfig.debug
    @@ -9,6 +9,15 @@ config PRINTK_TIME
    operations. This is useful for identifying long delays
    in kernel startup.

    +config PRINTK_CALLER
    + bool "Show caller PC on printks"
    + depends on PRINTK
    + help
    + Selecting this option causes printk output to include
    + the PC address of the printk call. This is useful for
    + kernels hackers to quickly locate the source code that
    + produced the message.
    +
    config ENABLE_WARN_DEPRECATED
    bool "Enable __deprecated logic"
    default y
    --
    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: [PATCH] printk.caller

    On Thu, 2 Oct 2008 16:21:15 -0700 (PDT)
    Roland McGrath wrote:

    > This adds the printk.caller=[0|1] boot parameter, default setting
    > controlled by CONFIG_PRINTK_CALLER. (This is modelled on printk.time
    > and CONFIG_PRINTK_TIME.)
    >
    > When this is set, each printk line is automagically prefixed with
    > "{0x123abc} " giving the PC address of that printk call (actually
    > the PC address just after the call).
    >
    > As a kernel hacker, I always hate having to grep for some fragment
    > of a message to find the code that generated it. But I always have
    > my -g vmlinux handy, so:
    > (gdb) info line *(0x123abc - 1)
    > is real handy (it pops the source up in an Emacs buffer).
    >


    hm. What do others think?

    >
    > ...
    >
    > +config PRINTK_CALLER
    > + bool "Show caller PC on printks"
    > + depends on PRINTK
    > + help
    > + Selecting this option causes printk output to include
    > + the PC address of the printk call. This is useful for
    > + kernels hackers to quickly locate the source code that
    > + produced the message.
    > +


    This is quite misleading. The config help implies that
    CONFIG_PRINTK_CALLER will enable the feature at compile time. But it
    doesn't - it just sets the boot-time enable/disable default.

    If you do this:

    #ifdef CONFIG_PRINTK_CALLER
    static int printk_caller = 1;
    #else
    #define printk_caller 0
    #endif

    then the implementation would somewhat reflect the config option.


    But I'd suggest that this thing is so small that it doesn't need a
    config option to enable the presence of the code - just make it
    unconditional.

    Also, I guess that the boot-time option is useful, but a runtime /proc
    knob might also be needed?

    --
    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: [PATCH] printk.caller

    I don't disagree with any of that.
    I followed the printk.time example closely.
    All those things are equally true of that option.


    Thanks,
    Roland
    --
    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: [PATCH] printk.caller

    On Thu, 2008-10-02 at 16:31 -0700, Andrew Morton wrote:
    > On Thu, 2 Oct 2008 16:21:15 -0700 (PDT)
    > Roland McGrath wrote:
    >
    > > This adds the printk.caller=[0|1] boot parameter, default setting
    > > controlled by CONFIG_PRINTK_CALLER. (This is modelled on printk.time
    > > and CONFIG_PRINTK_TIME.)
    > >
    > > When this is set, each printk line is automagically prefixed with
    > > "{0x123abc} " giving the PC address of that printk call (actually
    > > the PC address just after the call).
    > >
    > > As a kernel hacker, I always hate having to grep for some fragment
    > > of a message to find the code that generated it. But I always have
    > > my -g vmlinux handy, so:
    > > (gdb) info line *(0x123abc - 1)
    > > is real handy (it pops the source up in an Emacs buffer).
    > >

    >
    > hm. What do others think?


    git grep is usually plenty fast for me, but I guess different people,
    different tastes.

    Also, I always use addr2line instead of gdb,.. another not-to-the-point
    difference ;-)

    The only real downside to this patch for me is that it potentially
    increases the length of lines which means I;d have to stretch my serial
    console window, but I guess others might object to the puny increase in
    object size.

    Flip a coin.

    One tiny nit though:

    > + char pbuf[sizeof caller * 2 + sizeof "{0x} "];


    I thought we did sizeof() in-kernel.

    --
    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