RE: [PATCH v3] printk: fix zero-valued printk timestamps in early boot

Bird, Tim
2026-03-10T19:51:03Z

> -----Original Message-----
> From: Shashank Balaji <shashankbalaji02@gmail.com>
> Hi Tim,
>
> Tested-by: Shashank Balaji <shashankbalaji02@gmail.com>

Thanks for the testing!!

>
> ...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 :)

Nice catch! I'm considering either changing the comment, or
using a union here (or maybe both).

Thanks,
-- Tim