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

Hi Tim,

Tested-by: Shashank Balaji <[email protected]>

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