Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753001Ab2HCJQ0 (ORCPT ); Fri, 3 Aug 2012 05:16:26 -0400 Received: from devils.ext.ti.com ([198.47.26.153]:54186 "EHLO devils.ext.ti.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751361Ab2HCJQY (ORCPT ); Fri, 3 Aug 2012 05:16:24 -0400 From: Vikram Pandita To: , CC: , Vikram Pandita , Mike Turquette , Vimarsh Zutshi Subject: [PATCH v2] printk: add option to print cpu id Date: Fri, 3 Aug 2012 02:16:18 -0700 Message-ID: <1343985378-22330-1-git-send-email-vikram.pandita@ti.com> X-Mailer: git-send-email 1.7.9.5 MIME-Version: 1.0 Content-Type: text/plain Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 7380 Lines: 223 From: Vikram Pandita 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 Cc: Kay Sievers Cc: Mike Turquette Cc: Vimarsh Zutshi --- 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 -- 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/