From 649e6ee33f73ba1c4f2492c6de9aff2254b540cb Mon Sep 17 00:00:00 2001 From: Kay Sievers Date: Thu, 10 May 2012 04:30:45 +0200 Subject: [PATCH] printk() - restore timestamp printing at console output The output of the timestamps got lost with the conversion of the kmsg buffer to records; restore the old behavior. Document, that CONFIG_PRINTK_TIME now only controls the output of the timestamps in the syslog() system call and on the console, and not the recording of the timestamps. Cc: Joe Perches Cc: Linus Torvalds Cc: Sasha Levin Cc: Ingo Molnar Reported-by: Yinghai Lu Signed-off-by: Kay Sievers Signed-off-by: Greg Kroah-Hartman --- kernel/printk.c | 43 ++++++++++++++++++++++++++----------------- lib/Kconfig.debug | 16 ++++++++++------ 2 files changed, 36 insertions(+), 23 deletions(-) diff --git a/kernel/printk.c b/kernel/printk.c index 301fb0f09fbf..572941d7e5f7 100644 --- a/kernel/printk.c +++ b/kernel/printk.c @@ -786,6 +786,22 @@ static bool printk_time; #endif module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR); +static size_t prepend_timestamp(unsigned long long t, char *buf) +{ + unsigned long rem_ns; + + if (!printk_time) + return 0; + + if (!buf) + return 15; + + rem_ns = do_div(t, 1000000000); + + return sprintf(buf, "[%5lu.%06lu] ", + (unsigned long) t, rem_ns / 1000); +} + static int syslog_print_line(u32 idx, char *text, size_t size) { struct log *msg; @@ -800,9 +816,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size) len++; if (msg->level > 99) len++; - - if (printk_time) - len += 15; + len += prepend_timestamp(0, NULL); len += msg->text_len; len++; @@ -810,15 +824,7 @@ static int syslog_print_line(u32 idx, char *text, size_t size) } len = sprintf(text, "<%u>", msg->level); - - if (printk_time) { - unsigned long long t = msg->ts_nsec; - unsigned long rem_ns = do_div(t, 1000000000); - - len += sprintf(text + len, "[%5lu.%06lu] ", - (unsigned long) t, rem_ns / 1000); - } - + len += prepend_timestamp(msg->ts_nsec, text + len); if (len + msg->text_len > size) return -EINVAL; memcpy(text + len, log_text(msg), msg->text_len); @@ -1741,7 +1747,7 @@ again: for (;;) { struct log *msg; static char text[LOG_LINE_MAX]; - size_t len; + size_t len, l; int level; raw_spin_lock_irqsave(&logbuf_lock, flags); @@ -1761,10 +1767,13 @@ again: msg = log_from_idx(console_idx); level = msg->level & 7; - len = msg->text_len; - if (len+1 >= sizeof(text)) - len = sizeof(text)-1; - memcpy(text, log_text(msg), len); + + len = prepend_timestamp(msg->ts_nsec, text); + l = msg->text_len; + if (len + l + 1 >= sizeof(text)) + l = sizeof(text) - len - 1; + memcpy(text + len, log_text(msg), l); + len += l; text[len++] = '\n'; console_idx = log_next(console_idx); diff --git a/lib/Kconfig.debug b/lib/Kconfig.debug index ef8192bc0c33..e11934177030 100644 --- a/lib/Kconfig.debug +++ b/lib/Kconfig.debug @@ -3,12 +3,16 @@ config PRINTK_TIME bool "Show timing information on printks" depends on PRINTK help - Selecting this option causes timing information to be - included in printk output. This allows you to measure - the interval between kernel operations, including bootup - operations. This is useful for identifying long delays - in kernel startup. Or add printk.time=1 at boot-time. - See Documentation/kernel-parameters.txt + Selecting this option causes time stamps of the printk() + messages to be added to the output of the syslog() system + call and at the console. + + The timestamp is always recorded internally, and exported + to /dev/kmsg. This flag just specifies if the timestamp should + be included, not that the timestamp is recorded. + + The behavior is also controlled by the kernel command line + parameter printk.time=1. See Documentation/kernel-parameters.txt config DEFAULT_MESSAGE_LOGLEVEL int "Default message log level (1-7)" -- 2.30.2