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>

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