Messages in this thread |  | | Date | Tue, 10 Mar 2026 02:27:27 +0900 | | From | Shashank Balaji <> | | Subject | Re: [PATCH v3] printk: fix zero-valued printk timestamps in early boot |
| |
Hi Tim,
Tested-by: Shashank Balaji <shashankbalaji02@gmail.com>
...on top of rc3 on an AMD Ryzen 7 4800H laptop. This patch conflicts with these commits with trivial fixes:
032a730268a3 init/main.c: wrap long kernel cmdline when printing to logs 60325c27d3cf printk: Add execution context (task name/CPU) to printk_info 499f86de4f8c init/main: read bootconfig header with get_unaligned_le32()
Comment below.
On Tue, Feb 10, 2026 at 04:47:41PM -0700, Tim Bird wrote: > During early boot, printk timestamps are reported as zero before <snip> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 1d765ad242b8..5afd31c3345c 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -46,6 +46,7 @@ > #include <linux/ctype.h> > #include <linux/uio.h> > #include <linux/sched/clock.h> > +#include <linux/early_times.h> > #include <linux/sched/debug.h> > #include <linux/sched/task_stack.h> > #include <linux/panic.h> > @@ -75,6 +76,13 @@ EXPORT_SYMBOL(ignore_console_lock_warning); > > EXPORT_TRACEPOINT_SYMBOL_GPL(console); > > +#ifdef CONFIG_EARLY_PRINTK_TIMES > +cycles_t start_cycles; > +u64 start_ns; > +u32 early_mult, early_shift; > +u64 early_ts_offset; > +#endif > + > /* > * Low level drivers may need that to know if they can schedule in > * their unblank() callback or not. So let's export it. > @@ -639,7 +647,7 @@ static void append_char(char **pp, char *e, char c) > static ssize_t info_print_ext_header(char *buf, size_t size, > struct printk_info *info) > { > - u64 ts_usec = info->ts_nsec; > + u64 ts_usec = adjust_early_ts(info->ts_nsec); > char caller[20]; > #ifdef CONFIG_PRINTK_CALLER > u32 id = info->caller_id; > @@ -1352,7 +1360,11 @@ static size_t print_syslog(unsigned int level, char *buf) > > static size_t print_time(u64 ts, char *buf) > { > - unsigned long rem_nsec = do_div(ts, 1000000000); > + unsigned long rem_nsec; > + > + ts = adjust_early_ts(ts); > + > + rem_nsec = do_div(ts, 1000000000); > > return sprintf(buf, "[%5lu.%06lu]", > (unsigned long)ts, rem_nsec / 1000); > @@ -2242,6 +2254,8 @@ int vprintk_store(int facility, int level, > * timestamp with respect to the caller. > */ > ts_nsec = local_clock(); > + if (!ts_nsec) > + ts_nsec = early_cycles();
ts_nsec goes on to be stored in a struct printk_info's ts_nsec which is documented to be "timestamp in nanoseconds":
/* * Meta information about each stored message. * * All fields are set by the printk code except for @seq, which is * set by the ringbuffer code. */ struct printk_info { u64 seq; /* sequence number */ u64 ts_nsec; /* timestamp in nanoseconds */ u16 text_len; /* length of text message */ u8 facility; /* syslog facility */ u8 flags:5; /* internal record flags */ u8 level:3; /* syslog level */ u32 caller_id; /* thread id or processor id */ #ifdef CONFIG_PRINTK_EXECUTION_CTX u32 caller_id2; /* caller_id complement */ /* name of the task that generated the message */ char comm[TASK_COMM_LEN]; #endif
struct dev_printk_info dev_info; };
Since with this patch, ts_nsec can either be a timestamp in ns or a cycle count, the comment should be updated. Ideally, I'd like the member name to be changed as well to reflect the new semantic. I'm thinking ts_raw or ts_ns_or_cyc... naming is hard :)
Thanks, Shashank
|  |