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 <joe@perches.com>
Cc: Linus Torvalds <torvalds@linux-foundation.org>
Cc: Sasha Levin <levinsasha928@gmail.com>
Cc: Ingo Molnar <mingo@kernel.org>
Reported-by: Yinghai Lu <yinghai@kernel.org>
Signed-off-by: Kay Sievers <kay@vrfy.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>

diff --git a/kernel/printk.c b/kernel/printk.c
index 301fb0f09fbf11ee3f4f5b375691299af951da54..572941d7e5f75a6e79e9779afb4683bdf744b815 100644 (file)
--- 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 ef8192bc0c336a29976cc9cb583583305ab6ea93..e119341770308c2341bdc59b008ce6636b4492b3 100644 (file)
--- 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)"