[RFC patch 6/7] printk: Store mono/boot/real time timestamps

[Thomas Gleixner <tglx@linutronix.de>]

[-- Attachment #1: printk--Use-time-snapshot.patch --]
[-- Type: text/plain, Size: 5672 bytes --]

To allow reliable timestamp correlation, replace the clock MONOTONIC based
timestamp in the printk ringbuffer entries with a collection of MONOTONIC,
BOOTTIME and REALTIME timestamps.

This does not change the textual output, as this is a separate issue. For
tools which access a vmcore the new timestamp fields are separately
exported by name so the tools do not have to gain knowledge about struct
system_timestamps. The existing 'ts_nsec' timestamp, which is used by
existing tools is mapped to the clock MONOTONIC entry of the timestamp
collection.

Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
---
 kernel/printk/printk.c |   55 ++++++++++++++++++++++++++++---------------------
 1 file changed, 32 insertions(+), 23 deletions(-)

--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -352,13 +352,13 @@ enum log_flags {
 };
 
 struct printk_log {
-	u64 ts_nsec;		/* timestamp in nanoseconds */
-	u16 len;		/* length of entire record */
-	u16 text_len;		/* length of text buffer */
-	u16 dict_len;		/* length of dictionary buffer */
-	u8 facility;		/* syslog facility */
-	u8 flags:5;		/* internal record flags */
-	u8 level:3;		/* syslog level */
+	struct system_timestamps ts;	/* Timestamps in nanoseconds */
+	u16 len;			/* length of entire record */
+	u16 text_len;			/* length of text buffer */
+	u16 dict_len;			/* length of dictionary buffer */
+	u8 facility;			/* syslog facility */
+	u8 flags:5;			/* internal record flags */
+	u8 level:3;			/* syslog level */
 }
 #ifdef CONFIG_HAVE_EFFICIENT_UNALIGNED_ACCESS
 __packed __aligned(4)
@@ -577,8 +577,8 @@ static u32 truncate_msg(u16 *text_len, u
 }
 
 /* insert record into the buffer, discard old ones, update heads */
-static int log_store(int facility, int level,
-		     enum log_flags flags, u64 ts_nsec,
+static int log_store(int facility, int level, enum log_flags flags,
+		     struct system_timestamps *ts,
 		     const char *dict, u16 dict_len,
 		     const char *text, u16 text_len)
 {
@@ -621,10 +621,10 @@ static int log_store(int facility, int l
 	msg->facility = facility;
 	msg->level = level & 7;
 	msg->flags = flags & 0x1f;
-	if (ts_nsec > 0)
-		msg->ts_nsec = ts_nsec;
+	if (ts)
+		msg->ts = *ts;
 	else
-		msg->ts_nsec = ktime_get_mono_fast_ns();
+		ktime_get_fast_timestamps(&msg->ts);
 	memset(log_dict(msg) + dict_len, 0, pad_len);
 	msg->len = size;
 
@@ -687,7 +687,7 @@ static void append_char(char **pp, char
 static ssize_t msg_print_ext_header(char *buf, size_t size,
 				    struct printk_log *msg, u64 seq)
 {
-	u64 ts_usec = msg->ts_nsec;
+	u64 ts_usec = msg->ts.mono;
 
 	do_div(ts_usec, 1000);
 
@@ -1021,7 +1021,14 @@ void log_buf_vmcoreinfo_setup(void)
 	 * parse it and detect any changes to structure down the line.
 	 */
 	VMCOREINFO_STRUCT_SIZE(printk_log);
-	VMCOREINFO_OFFSET(printk_log, ts_nsec);
+	/*
+	 * The timestamps fields are exported explicitely so older tools
+	 * which only know "ts_nsec" still work and newer tools do not need
+	 * to know about the struct system_timestamps layout.
+	 */
+	VMCOREINFO_FIELD_AND_OFFSET(printk_log, ts_nsec, ts.mono);
+	VMCOREINFO_FIELD_AND_OFFSET(printk_log, ts_boot_nsec, ts.boot);
+	VMCOREINFO_FIELD_AND_OFFSET(printk_log, ts_real_nsec, ts.real);
 	VMCOREINFO_OFFSET(printk_log, len);
 	VMCOREINFO_OFFSET(printk_log, text_len);
 	VMCOREINFO_OFFSET(printk_log, dict_len);
@@ -1204,20 +1211,21 @@ static inline void boot_delay_msec(int l
 static bool printk_time = IS_ENABLED(CONFIG_PRINTK_TIME);
 module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);
 
-static size_t print_time(u64 ts, char *buf)
+static size_t print_time(const struct system_timestamps *ts, char *buf)
 {
 	unsigned long rem_nsec;
+	u64 mono = ts->mono;
 
 	if (!printk_time)
 		return 0;
 
-	rem_nsec = do_div(ts, 1000000000);
+	rem_nsec = do_div(mono, 1000000000);
 
 	if (!buf)
-		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)ts);
+		return snprintf(NULL, 0, "[%5lu.000000] ", (unsigned long)mono);
 
 	return sprintf(buf, "[%5lu.%06lu] ",
-		       (unsigned long)ts, rem_nsec / 1000);
+		       (unsigned long)mono, rem_nsec / 1000);
 }
 
 static size_t print_prefix(const struct printk_log *msg, bool syslog, char *buf)
@@ -1239,7 +1247,7 @@ static size_t print_prefix(const struct
 		}
 	}
 
-	len += print_time(msg->ts_nsec, buf ? buf + len : NULL);
+	len += print_time(&msg->ts, buf ? buf + len : NULL);
 	return len;
 }
 
@@ -1599,7 +1607,7 @@ static struct cont {
 	char buf[LOG_LINE_MAX];
 	size_t len;			/* length == 0 means unused buffer */
 	struct task_struct *owner;	/* task of first print*/
-	u64 ts_nsec;			/* time of first print */
+	struct system_timestamps ts;	/* time of first print */
 	u8 level;			/* log level of first message */
 	u8 facility;			/* log facility of first message */
 	enum log_flags flags;		/* prefix, newline flags */
@@ -1610,7 +1618,7 @@ static void cont_flush(void)
 	if (cont.len == 0)
 		return;
 
-	log_store(cont.facility, cont.level, cont.flags, cont.ts_nsec,
+	log_store(cont.facility, cont.level, cont.flags, &cont.ts,
 		  NULL, 0, cont.buf, cont.len);
 	cont.len = 0;
 }
@@ -1631,7 +1639,7 @@ static bool cont_add(int facility, int l
 		cont.facility = facility;
 		cont.level = level;
 		cont.owner = current;
-		cont.ts_nsec = ktime_get_mono_fast_ns();
+		ktime_get_fast_timestamps(&cont.ts);
 		cont.flags = flags;
 	}
 
@@ -1677,7 +1685,8 @@ static size_t log_output(int facility, i
 	}
 
 	/* Store it in the record log */
-	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
+	return log_store(facility, level, lflags, NULL, dict, dictlen, text,
+			 text_len);
 }
 
 asmlinkage int vprintk_emit(int facility, int level,