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 <[email protected]> --- 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,
