On Fri 2020-08-14 12:19:33, Thomas Gleixner wrote: > printk intends to store various timestamps (MONOTONIC, REALTIME, BOOTTIME) > to make correlation of dmesg accross different machines easier. > > The NMI safe timekeeper allows to retrieve these timestamps from any > context. For both patches: Tested-by: Petr Mladek <pmladek@xxxxxxxx> I am not familiar with the timekeeping code so that I could not provide a valuable review. Anyway, the patches seem to work as expected. The interface is perfectly fine for printk() needs. I tested them with the patch below. The first timestamps appear as early as before: [ 0.000000] [ 0.000000][1970-01-01T00:00:00][ T0] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] [ 0.000000][1970-01-01T00:00:00][ T0] kvm-clock: cpu 0, msr 129c01001, primary cpu clock [ 0.000000] [ 0.000000][1970-01-01T00:00:00][ T0] kvm-clock: using sched offset of 56519600356309 cycles [ 0.000008] [ 0.000008][1970-01-01T00:00:00][ T0] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000022] [ 0.000022][1970-01-01T00:00:00][ T0] tsc: Detected 2112.000 MHz processor [ 0.000835] [ 0.000835][1970-01-01T00:00:00][ T0] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved The realtime timestamps get ready later as expected: [ 0.073075] [ 0.073075][1970-01-01T00:00:00][ T0] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=3 [ 0.075847] [ 0.075847][1970-01-01T00:00:00][ T0] NR_IRQS: 524544, nr_irqs: 448, preallocated irqs: 16 [ 0.076014] [ 0.076014][2020-08-20T07:58:46][ T0] Console: colour dummy device 80x25 [ 0.076014] [ 0.076014][2020-08-20T07:58:46][ T0] printk: console [tty0] enabled Also suspend resume seems to work as expected. I tested it the follwing way: echo core > /sys/power/pm_test echo reboot > /sys/power/disk echo disk > /sys/power/state and the result is: [ 224.422540] [ 224.422540][2020-08-20T08:02:31][ T5124] Disabling non-boot CPUs ... [ 224.424171] [ 224.424171][2020-08-20T08:02:31][ T15] IRQ fixup: irq 21 move in progress, old vector 36 [ 224.425304] [ 224.425304][2020-08-20T08:02:31][ T5124] smpboot: CPU 1 is now offline [ 224.426664] [ 224.426664][2020-08-20T08:02:31][ T20] IRQ 21: no longer affine to CPU2 [ 224.426685] [ 224.426685][2020-08-20T08:02:31][ T20] IRQ 24: no longer affine to CPU2 [ 224.426717] [ 224.426717][2020-08-20T08:02:31][ T20] IRQ 27: no longer affine to CPU2 [ 224.427765] [ 224.427765][2020-08-20T08:02:31][ T5124] smpboot: CPU 2 is now offline [ 224.428016] [ 224.428016][2020-08-20T08:02:31][ T5124] PM: hibernation: debug: Waiting for 5 seconds. [ 224.428218] [ 229.618141][2020-08-20T08:02:36][ T5124] Enabling non-boot CPUs ... ^^^ ^^^ ^^ [ 224.428560] [ 229.618483][2020-08-20T08:02:36][ T5124] x86: Booting SMP configuration: [ 224.428564] [ 229.618486][2020-08-20T08:02:36][ T5124] smpboot: Booting Node 0 Processor 1 APIC 0x1 [ 224.428766] [ 229.618688][2020-08-20T08:02:36][ T0] kvm-clock: cpu 1, msr 129c01041, secondary cpu clock [ 224.449192] [ 229.639115][2020-08-20T08:02:36][ T14] kvm-guest: stealtime: cpu 1, msr 17fbf2080 And here is the patch that I used for testing: >From 39bdfebfa94fc55616fe23f2f0b80e06479b65e0 Mon Sep 17 00:00:00 2001 From: Petr Mladek <pmladek@xxxxxxxx> Date: Thu, 20 Aug 2020 10:18:57 +0200 Subject: [PATCH] printk: Test using all three timestamps: mono, boot, real Test timekeeper enhancements proposed at https://lore.kernel.org/r/20200814101933.574326079@xxxxxxxxxxxxx Allow to store and show all three timestamp (mono, boot, real). It is not final solution. The prefix takes 83 characters that might make the real text invisible or hard to read. Fragments of seconds are lost in when printing real time timestamp. Offset is not provided for crashdump tools. Only syslog interface is supported. The log can be seen on consoles or via: dmesg -S Signed-off-by: Petr Mladek <pmladek@xxxxxxxx> --- kernel/printk/printk.c | 40 ++++++++++++++++++++++++++-------------- 1 file changed, 26 insertions(+), 14 deletions(-) diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 9b75f6bfc333..329f3595b024 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -366,7 +366,7 @@ enum log_flags { }; struct printk_log { - u64 ts_nsec; /* timestamp in nanoseconds */ + struct ktime_timestamps ts; /* timestamps */ u16 len; /* length of entire record */ u16 text_len; /* length of text buffer */ u16 dict_len; /* length of dictionary buffer */ @@ -443,7 +443,7 @@ static u64 clear_seq; static u32 clear_idx; #ifdef CONFIG_PRINTK_CALLER -#define PREFIX_MAX 48 +#define PREFIX_MAX 48+14+21 #else #define PREFIX_MAX 32 #endif @@ -614,7 +614,7 @@ static u32 truncate_msg(u16 *text_len, u16 *trunc_msg_len, /* insert record into the buffer, discard old ones, update heads */ static int log_store(u32 caller_id, int facility, int level, - enum log_flags flags, u64 ts_nsec, + enum log_flags flags, struct ktime_timestamps *ts, const char *dict, u16 dict_len, const char *text, u16 text_len) { @@ -657,10 +657,10 @@ static int log_store(u32 caller_id, int facility, int level, 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 = local_clock(); + ktime_get_fast_timestamps(&msg->ts); #ifdef CONFIG_PRINTK_CALLER msg->caller_id = caller_id; #endif @@ -726,7 +726,7 @@ static void append_char(char **pp, char *e, char c) 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; char caller[20]; #ifdef CONFIG_PRINTK_CALLER u32 id = msg->caller_id; @@ -1090,8 +1090,8 @@ 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); - VMCOREINFO_OFFSET(printk_log, len); +/* VMCOREINFO_OFFSET(printk_log, ts); + */ VMCOREINFO_OFFSET(printk_log, len); VMCOREINFO_OFFSET(printk_log, text_len); VMCOREINFO_OFFSET(printk_log, dict_len); #ifdef CONFIG_PRINTK_CALLER @@ -1308,6 +1308,14 @@ static size_t print_time(u64 ts, char *buf) (unsigned long)ts, rem_nsec / 1000); } +static size_t print_real_time(u64 ts, char *buf) +{ + u64 ts_nsec = ts / 1000000000; + + return sprintf(buf, "[%ptT]", &ts_nsec); +} + + #ifdef CONFIG_PRINTK_CALLER static size_t print_caller(u32 id, char *buf) { @@ -1329,8 +1337,12 @@ static size_t print_prefix(const struct printk_log *msg, bool syslog, if (syslog) len = print_syslog((msg->facility << 3) | msg->level, buf); - if (time) - len += print_time(msg->ts_nsec, buf + len); + + if (time) { + len += print_time(msg->ts.mono, buf + len); + len += print_time(msg->ts.boot, buf + len); + len += print_real_time(msg->ts.real, buf + len); + } len += print_caller(msg->caller_id, buf + len); @@ -1855,7 +1867,7 @@ static struct cont { char buf[LOG_LINE_MAX]; size_t len; /* length == 0 means unused buffer */ u32 caller_id; /* printk_caller_id() of first print */ - u64 ts_nsec; /* time of first print */ + struct ktime_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 */ @@ -1867,7 +1879,7 @@ static void cont_flush(void) return; log_store(cont.caller_id, cont.facility, cont.level, cont.flags, - cont.ts_nsec, NULL, 0, cont.buf, cont.len); + &cont.ts, NULL, 0, cont.buf, cont.len); cont.len = 0; } @@ -1884,7 +1896,7 @@ static bool cont_add(u32 caller_id, int facility, int level, cont.facility = facility; cont.level = level; cont.caller_id = caller_id; - cont.ts_nsec = local_clock(); + ktime_get_fast_timestamps(&cont.ts); cont.flags = flags; } -- 2.26.2 _______________________________________________ kexec mailing list kexec@xxxxxxxxxxxxxxxxxxx http://lists.infradead.org/mailman/listinfo/kexec
