lkml.org 
[lkml]   [2012]   [Aug]   [3]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    Patch in this message
    /
    From
    Subject[PATCH v2] printk: add option to print cpu id
    Date
    From: Vikram Pandita <vikram.pandita@ti.com>

    Introduce config option to enable CPU id reporting for printk() calls.

    Example logs with this option enabled look like:
    [1] [ 2.328613] usbcore: registered new interface driver libusual
    [1] [ 2.335418] usbcore: registered new interface driver usbtest
    [1] [ 2.342803] mousedev: PS/2 mouse device common for all mice
    [0] [ 2.352600] twl_rtc twl_rtc: Power up reset detected.
    [0] [ 2.359191] twl_rtc twl_rtc: Enabling TWL-RTC
    [1] [ 2.367797] twl_rtc twl_rtc: rtc core: registered twl_rtc as rtc0
    [1] [ 2.375274] i2c /dev entries driver
    [1] [ 2.382324] Driver for 1-wire Dallas network protocol.

    Its sometimes very useful to have printk also print the CPU Identifier
    that executed the call. This has helped to debug various SMP issues on shipping
    products.

    Known limitation is if the system gets preempted between function call and
    actual printk, the reported cpu-id might not be accurate. But most of the
    times its seen to give a good feel of how the N cpu's in the system are
    getting loaded.

    Signed-off-by: Vikram Pandita <vikram.pandita@ti.com>
    Cc: Kay Sievers <kay@vrfy.org>
    Cc: Mike Turquette <mturquette@linaro.org>
    Cc: Vimarsh Zutshi <vimarsh.zutshi@gmail.com>
    ---
    v1: initial version - had wrong cpuid logging mechanism
    v2: fixed as per review comments from Kay Sievers

    kernel/printk.c | 51 +++++++++++++++++++++++++++++++++++++++++----------
    lib/Kconfig.debug | 13 +++++++++++++
    2 files changed, 54 insertions(+), 10 deletions(-)

    diff --git a/kernel/printk.c b/kernel/printk.c
    index 6a76ab9..64f4a1b 100644
    --- a/kernel/printk.c
    +++ b/kernel/printk.c
    @@ -208,6 +208,7 @@ struct log {
    u8 facility; /* syslog facility */
    u8 flags:5; /* internal record flags */
    u8 level:3; /* syslog level */
    + u8 cpuid; /* cpu invoking the log */
    };

    /*
    @@ -305,7 +306,8 @@ static u32 log_next(u32 idx)
    static void log_store(int facility, int level,
    enum log_flags flags, u64 ts_nsec,
    const char *dict, u16 dict_len,
    - const char *text, u16 text_len)
    + const char *text, u16 text_len,
    + const u8 cpuid)
    {
    struct log *msg;
    u32 size, pad_len;
    @@ -356,6 +358,7 @@ static void log_store(int facility, int level,
    msg->ts_nsec = local_clock();
    memset(log_dict(msg) + dict_len, 0, pad_len);
    msg->len = sizeof(struct log) + text_len + dict_len + pad_len;
    + msg->cpuid = cpuid;

    /* insert message */
    log_next_idx += msg->len;
    @@ -855,6 +858,25 @@ static size_t print_time(u64 ts, char *buf)
    (unsigned long)ts, rem_nsec / 1000);
    }

    +#if defined(CONFIG_PRINTK_CPUID)
    +static bool printk_cpuid = 1;
    +#else
    +static bool printk_cpuid;
    +#endif
    +module_param_named(cpuid, printk_cpuid, bool, S_IRUGO | S_IWUSR);
    +
    +static size_t print_cpuid(u8 cpuid, char *buf)
    +{
    +
    + if (!printk_cpuid)
    + return 0;
    +
    + if (!buf)
    + return 4;
    +
    + return sprintf(buf, "[%1d] ", cpuid);
    +}
    +
    static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
    {
    size_t len = 0;
    @@ -874,6 +896,7 @@ static size_t print_prefix(const struct log *msg, bool syslog, char *buf)
    }
    }

    + len += print_cpuid(msg->cpuid, buf ? buf + len : NULL);
    len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
    return len;
    }
    @@ -1387,6 +1410,7 @@ static struct cont {
    u64 ts_nsec; /* time of first print */
    u8 level; /* log level of first message */
    u8 facility; /* log level of first message */
    + u8 cpuid; /* cpu invoking the logging request */
    enum log_flags flags; /* prefix, newline flags */
    bool flushed:1; /* buffer sealed and committed */
    } cont;
    @@ -1405,7 +1429,8 @@ static void cont_flush(enum log_flags flags)
    * line. LOG_NOCONS suppresses a duplicated output.
    */
    log_store(cont.facility, cont.level, flags | LOG_NOCONS,
    - cont.ts_nsec, NULL, 0, cont.buf, cont.len);
    + cont.ts_nsec, NULL, 0, cont.buf, cont.len,
    + cont.cpuid);
    cont.flags = flags;
    cont.flushed = true;
    } else {
    @@ -1414,12 +1439,14 @@ static void cont_flush(enum log_flags flags)
    * just submit it to the store and free the buffer.
    */
    log_store(cont.facility, cont.level, flags, 0,
    - NULL, 0, cont.buf, cont.len);
    + NULL, 0, cont.buf, cont.len,
    + cont.cpuid);
    cont.len = 0;
    }
    }

    -static bool cont_add(int facility, int level, const char *text, size_t len)
    +static bool cont_add(int facility, int level, const char *text, size_t len,
    + const u8 cpuid)
    {
    if (cont.len && cont.flushed)
    return false;
    @@ -1442,6 +1469,7 @@ static bool cont_add(int facility, int level, const char *text, size_t len)

    memcpy(cont.buf + cont.len, text, len);
    cont.len += len;
    + cont.cpuid = cpuid;

    if (cont.len > (sizeof(cont.buf) * 80) / 100)
    cont_flush(LOG_CONT);
    @@ -1455,7 +1483,8 @@ static size_t cont_print_text(char *text, size_t size)
    size_t len;

    if (cont.cons == 0 && (console_prev & LOG_NEWLINE)) {
    - textlen += print_time(cont.ts_nsec, text);
    + textlen += print_cpuid(cont.cpuid, text);
    + textlen += print_time(cont.ts_nsec, text + textlen);
    size -= textlen;
    }

    @@ -1527,7 +1556,7 @@ asmlinkage int vprintk_emit(int facility, int level,
    printed_len += strlen(recursion_msg);
    /* emit KERN_CRIT message */
    log_store(0, 2, LOG_PREFIX|LOG_NEWLINE, 0,
    - NULL, 0, recursion_msg, printed_len);
    + NULL, 0, recursion_msg, printed_len, this_cpu);
    }

    /*
    @@ -1577,9 +1606,9 @@ asmlinkage int vprintk_emit(int facility, int level,
    cont_flush(LOG_NEWLINE);

    /* buffer line if possible, otherwise store it right away */
    - if (!cont_add(facility, level, text, text_len))
    + if (!cont_add(facility, level, text, text_len, this_cpu))
    log_store(facility, level, lflags | LOG_CONT, 0,
    - dict, dictlen, text, text_len);
    + dict, dictlen, text, text_len, this_cpu);
    } else {
    bool stored = false;

    @@ -1591,13 +1620,15 @@ asmlinkage int vprintk_emit(int facility, int level,
    */
    if (cont.len && cont.owner == current) {
    if (!(lflags & LOG_PREFIX))
    - stored = cont_add(facility, level, text, text_len);
    + stored = cont_add(facility, level, text, text_len,
    + this_cpu);
    cont_flush(LOG_NEWLINE);
    }

    if (!stored)
    log_store(facility, level, lflags, 0,
    - dict, dictlen, text, text_len);
    + dict, dictlen, text, text_len,
    + this_cpu);
    }
    printed_len += text_len;

    diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug
    index 2403a63..139b2b1 100644
    --- a/lib/Kconfig.debug
    +++ b/lib/Kconfig.debug
    @@ -14,6 +14,19 @@ config PRINTK_TIME
    The behavior is also controlled by the kernel command line
    parameter printk.time=1. See Documentation/kernel-parameters.txt

    +config PRINTK_CPUID
    + bool "Show cpu id information on printks"
    + depends on PRINTK
    + help
    + Selecting this option causes cpu identifier to be added to the
    + output of the syslog() system call and at the console.
    +
    + This flag just specifies if the cpu-id should
    + be included.
    +
    + The behavior is also controlled by the kernel command line
    + parameter printk.cpuid=1.
    +
    config DEFAULT_MESSAGE_LOGLEVEL
    int "Default message log level (1-7)"
    range 1 7
    --
    1.7.9.5


    \
     
     \ /
      Last update: 2012-08-03 12:01    [W:2.159 / U:0.232 seconds]
    ©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site