During early boot, printk timestamps are reported as zero before
kernel timekeeping starts (e.g. before time_init()).  This
hinders boot-time optimization efforts.  This period is about 400
milliseconds for many current desktop and embedded machines
running Linux.

Add support to save cycles during early boot, and output correct
timestamp values after timekeeping is initialized.  get_cycles()
is operational on arm64 and x86_64 from kernel start.  Add code
and variables to save calibration values used to later convert
cycle counts to time values in the early printks.  Add a config
to control the feature.

This yields non-zero timestamps for printks from the very start
of kernel execution.  The timestamps are relative to the start of
the architecture-specified counter used in get_cycles
(e.g. the TSC on x86_64 and cntvct_el0 on arm64).

All timestamps reflect time from processor power-on instead of
time from the kernel's timekeeping initialization.

Signed-off-by: Tim Bird <tim.bird@sony.com>
---
V2->V3
 Default CONFIG option to 'n'
 Move more code from into early_times.h
  (reducing ifdefs in init/main.c)
 Use math64 helper routines
 Use cycles_t instead of u64 type
 Add #defines for EARLY_CYCLES_BIT and MASK
 Invert if logic in adjust_early_ts()
 (note: no change to 'depends on' in Kconfig entry)

V1->V2
 Remove calibration CONFIG vars
 Add 'depends on' to restrict arches (to handle ppc bug)
 Add early_ts_offset to avoid discontinuity
 Save cycles in ts_nsec, and convert on output
 Move conditional code to include file (early_times.h)

 include/linux/early_times.h | 85 +++++++++++++++++++++++++++++++++++++
 init/Kconfig                | 14 ++++++
 init/main.c                 |  6 +++
 kernel/printk/printk.c      | 18 +++++++-
 4 files changed, 121 insertions(+), 2 deletions(-)
 create mode 100644 include/linux/early_times.h

diff --git a/include/linux/early_times.h b/include/linux/early_times.h
new file mode 100644
index 000000000000..05388dcb8573
--- /dev/null
+++ b/include/linux/early_times.h
@@ -0,0 +1,85 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
+#define _KERNEL_PRINTK_EARLY_TIMES_H
+
+#include <linux/timex.h>
+#include <linux/clocksource.h>
+
+/* use high bit of a u64 to indicate cycles instead of a timestamp */
+#define EARLY_CYCLES_BIT	BIT_ULL(63)
+#define EARLY_CYCLES_MASK	~(BIT_ULL(63))
+
+#if defined(CONFIG_EARLY_PRINTK_TIMES)
+extern cycles_t start_cycles;
+extern u64 start_ns;
+extern u32 early_mult, early_shift;
+extern u64 early_ts_offset;
+
+static inline void early_times_start_calibration(void)
+{
+	start_cycles = get_cycles();
+	start_ns = local_clock();
+}
+
+static inline void early_times_finish_calibration(void)
+{
+	cycles_t end_cycles;
+	u64 end_ns;
+
+	/* set calibration data for early_printk_times */
+	end_cycles = get_cycles();
+	end_ns = local_clock();
+	clocks_calc_mult_shift(&early_mult, &early_shift,
+		mul_u64_u64_div_u64(end_cycles - start_cycles,
+			NSEC_PER_SEC, end_ns - start_ns),
+		NSEC_PER_SEC, 100);
+	early_ts_offset = mul_u64_u32_shr(start_cycles, early_mult, early_shift) - start_ns;
+
+	pr_debug("Early printk times: mult=%u, shift=%u, offset=%llu ns\n",
+		early_mult, early_shift, early_ts_offset);
+}
+
+static inline u64 early_cycles(void)
+{
+	return (get_cycles() | EARLY_CYCLES_BIT);
+}
+
+/*
+ * adjust_early_ts detects whether ts in is cycles or nanoseconds
+ * and converts it or adjusts it, taking into account the offset
+ * from cycle-counter start.
+ *
+ * Note that early_mult may be 0, but that's OK because
+ * we'll just multiply by 0 and return 0. This will
+ * only occur if we're outputting a printk message
+ * before the calibration of the early timestamp.
+ * Any output after user space start (eg. from dmesg or
+ * journalctl) will show correct values.
+ */
+static inline u64 adjust_early_ts(u64 ts)
+{
+	if (likely(!(ts & EARLY_CYCLES_BIT)))
+		/* if timestamp is not in cycles, just add offset */
+		return ts + early_ts_offset;
+
+	/* mask high bit and convert to nanoseconds */
+	return mul_u64_u32_shr(ts & EARLY_CYCLES_MASK, early_mult, early_shift);
+}
+
+#else
+# define early_times_start_calibration() do { } while (0)
+# define early_times_finish_calibration() do { } while (0)
+
+static inline u64 early_cycles(void)
+{
+	return 0;
+}
+
+static inline u64 adjust_early_ts(u64 ts)
+{
+	return ts;
+}
+#endif /* CONFIG_EARLY_PRINTK_TIMES */
+
+#endif /* _KERNEL_PRINTK_EARLY_TIMES_H */
diff --git a/init/Kconfig b/init/Kconfig
index fa79feb8fe57..a928c1efb09d 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -777,6 +777,20 @@ config IKHEADERS
 	  or similar programs.  If you build the headers as a module, a module called
 	  kheaders.ko is built which can be loaded on-demand to get access to headers.
 
+config EARLY_PRINTK_TIMES
+	bool "Show non-zero printk timestamps early in boot"
+	default n
+	depends on PRINTK
+	depends on ARM64 || X86_64
+	help
+	  Use a cycle-counter to provide printk timestamps during
+	  early boot.  This allows seeing timestamps for printks that
+	  would otherwise show as 0.  Note that this will shift the
+	  printk timestamps to be relative to processor power on, instead
+	  of relative to the start of kernel timekeeping.  This should be
+	  closer to machine power on, giving a better indication of
+	  overall boot time.
+
 config LOG_BUF_SHIFT
 	int "Kernel log buffer size (16 => 64KB, 17 => 128KB)"
 	range 12 25
diff --git a/init/main.c b/init/main.c
index b84818ad9685..d5774aec1aff 100644
--- a/init/main.c
+++ b/init/main.c
@@ -104,6 +104,7 @@
 #include <linux/pidfs.h>
 #include <linux/ptdump.h>
 #include <linux/time_namespace.h>
+#include <linux/early_times.h>
 #include <net/net_namespace.h>
 
 #include <asm/io.h>
@@ -1118,6 +1119,9 @@ void start_kernel(void)
 	timekeeping_init();
 	time_init();
 
+	/* This must be after timekeeping is initialized */
+	early_times_start_calibration();
+
 	/* This must be after timekeeping is initialized */
 	random_init();
 
@@ -1600,6 +1604,8 @@ static int __ref kernel_init(void *unused)
 
 	do_sysctl_args();
 
+	early_times_finish_calibration();
+
 	if (ramdisk_execute_command) {
 		ret = run_init_process(ramdisk_execute_command);
 		if (!ret)
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();
 
 	caller_id = printk_caller_id();
 
-- 
2.43.0

On Tue, Feb 10 2026 at 16:47, Tim Bird wrote:
> During early boot, printk timestamps are reported as zero before
> kernel timekeeping starts (e.g. before time_init()).  This
> hinders boot-time optimization efforts.  This period is about 400
> milliseconds for many current desktop and embedded machines
> running Linux.
>
> Add support to save cycles during early boot, and output correct
> timestamp values after timekeeping is initialized.  get_cycles()
> is operational on arm64 and x86_64 from kernel start.  Add code
> and variables to save calibration values used to later convert
> cycle counts to time values in the early printks.  Add a config
> to control the feature.
>
> This yields non-zero timestamps for printks from the very start
> of kernel execution.  The timestamps are relative to the start of
> the architecture-specified counter used in get_cycles
> (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
>
> All timestamps reflect time from processor power-on instead of
> time from the kernel's timekeeping initialization.

Can we pretty please _not_ introduce yet another side channel to
generate time stamps?

printk()

   time_ns = local_clock();

local_clock()
  local_clock_noinstr()
  	// After boot
	if (static_branch_likely(&__sched_clock_stable))
		return sched_clock_noinstr() + __sched_clock_offset;

	// Before sched_clock_init()
	if (!static_branch_likely(&sched_clock_running))
		return sched_clock_noinstr();

	clock = sched_clock_local(this_scd());

On x86:
sched_clock_noinstr()
  // bare metal
  native_sched_clock()
     // After TSC calibration
     if (static_branch_likely(&__use_tsc)) {
       ...
     }

  // Jiffies fallback.

So the obvious solution is to expand the fallback with:

    if (tsc_available())
    	return tsc_early_uncalibrated();

    return jiffies ....;

As this needs to be supported by the architecture/platform in any case
there is close to zero benefit from creating complicated generic
infrastructure for this.

Thanks,

        tglx

Hi again,

On Tue, Feb 10, 2026 at 04:47:41PM -0700, Tim Bird wrote:
> During early boot, printk timestamps are reported as zero before
> kernel timekeeping starts (e.g. before time_init()).  This
> hinders boot-time optimization efforts.  This period is about 400
> milliseconds for many current desktop and embedded machines
> running Linux.
> 
> Add support to save cycles during early boot, and output correct
> timestamp values after timekeeping is initialized.  get_cycles()
> is operational on arm64 and x86_64 from kernel start.  Add code
> and variables to save calibration values used to later convert
> cycle counts to time values in the early printks.  Add a config
> to control the feature.
> 
> This yields non-zero timestamps for printks from the very start
> of kernel execution.  The timestamps are relative to the start of
> the architecture-specified counter used in get_cycles
> (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> 
> All timestamps reflect time from processor power-on instead of
> time from the kernel's timekeeping initialization.
> 
> Signed-off-by: Tim Bird <tim.bird@sony.com>

So if a console is read before the cycles -> timestamp conversion can
happen, then they'll see 0. But reading from userspace will give the
right timestamps.

Based on the previous discussions, to address this possible confusion,
if changing the timestamp format, like adding '?', is a no-go because
of concerns of breaking existing monitoring tools, what about appending
something to the printk string after the timestamp? Hmm, no, that'll
affect grep'ability _and_ may break monitoring tools. Or what about a
pr_warn() early in boot to warn about the possible timestamp difference?

At the very least the possibility of this difference should be
documented in the Kconfig description.

Continuing below...

> ---
> V2->V3
>  Default CONFIG option to 'n'
>  Move more code from into early_times.h
>   (reducing ifdefs in init/main.c)
>  Use math64 helper routines
>  Use cycles_t instead of u64 type
>  Add #defines for EARLY_CYCLES_BIT and MASK
>  Invert if logic in adjust_early_ts()
>  (note: no change to 'depends on' in Kconfig entry)
> 
> V1->V2
>  Remove calibration CONFIG vars
>  Add 'depends on' to restrict arches (to handle ppc bug)
>  Add early_ts_offset to avoid discontinuity
>  Save cycles in ts_nsec, and convert on output
>  Move conditional code to include file (early_times.h)
> 
>  include/linux/early_times.h | 85 +++++++++++++++++++++++++++++++++++++
>  init/Kconfig                | 14 ++++++
>  init/main.c                 |  6 +++
>  kernel/printk/printk.c      | 18 +++++++-
>  4 files changed, 121 insertions(+), 2 deletions(-)
>  create mode 100644 include/linux/early_times.h
> 
> diff --git a/include/linux/early_times.h b/include/linux/early_times.h
> new file mode 100644
> index 000000000000..05388dcb8573
> --- /dev/null
> +++ b/include/linux/early_times.h
> @@ -0,0 +1,85 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
> +#define _KERNEL_PRINTK_EARLY_TIMES_H
> +
> +#include <linux/timex.h>
> +#include <linux/clocksource.h>
> +
> +/* use high bit of a u64 to indicate cycles instead of a timestamp */
> +#define EARLY_CYCLES_BIT	BIT_ULL(63)
> +#define EARLY_CYCLES_MASK	~(BIT_ULL(63))
> +
> +#if defined(CONFIG_EARLY_PRINTK_TIMES)
> +extern cycles_t start_cycles;
> +extern u64 start_ns;
> +extern u32 early_mult, early_shift;
> +extern u64 early_ts_offset;
> +
> +static inline void early_times_start_calibration(void)
> +{
> +	start_cycles = get_cycles();
> +	start_ns = local_clock();
> +}
> +
> +static inline void early_times_finish_calibration(void)
> +{
> +	cycles_t end_cycles;
> +	u64 end_ns;
> +
> +	/* set calibration data for early_printk_times */
> +	end_cycles = get_cycles();
> +	end_ns = local_clock();
> +	clocks_calc_mult_shift(&early_mult, &early_shift,
> +		mul_u64_u64_div_u64(end_cycles - start_cycles,
> +			NSEC_PER_SEC, end_ns - start_ns),
> +		NSEC_PER_SEC, 100);
> +	early_ts_offset = mul_u64_u32_shr(start_cycles, early_mult, early_shift) - start_ns;
> +
> +	pr_debug("Early printk times: mult=%u, shift=%u, offset=%llu ns\n",
> +		early_mult, early_shift, early_ts_offset);
> +}
> +
> +static inline u64 early_cycles(void)
> +{
> +	return (get_cycles() | EARLY_CYCLES_BIT);
> +}
> +
> +/*
> + * adjust_early_ts detects whether ts in is cycles or nanoseconds
> + * and converts it or adjusts it, taking into account the offset
> + * from cycle-counter start.
> + *
> + * Note that early_mult may be 0, but that's OK because
> + * we'll just multiply by 0 and return 0. This will
> + * only occur if we're outputting a printk message
> + * before the calibration of the early timestamp.
> + * Any output after user space start (eg. from dmesg or
> + * journalctl) will show correct values.
> + */
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> +	if (likely(!(ts & EARLY_CYCLES_BIT)))
> +		/* if timestamp is not in cycles, just add offset */
> +		return ts + early_ts_offset;
> +
> +	/* mask high bit and convert to nanoseconds */
> +	return mul_u64_u32_shr(ts & EARLY_CYCLES_MASK, early_mult, early_shift);
> +}
> +
> +#else
> +# define early_times_start_calibration() do { } while (0)
> +# define early_times_finish_calibration() do { } while (0)
> +
> +static inline u64 early_cycles(void)
> +{
> +	return 0;
> +}
> +
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> +	return ts;
> +}
> +#endif /* CONFIG_EARLY_PRINTK_TIMES */
> +
> +#endiV
> diff --git a/init/Kconfig b/init/Kconfig
> index fa79feb8fe57..a928c1efb09d 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -777,6 +777,20 @@ config IKHEADERS
>  	  or similar programs.  If you build the headers as a module, a module called
>  	  kheaders.ko is built which can be loaded on-demand to get access to headers.
>  
> +config EARLY_PRINTK_TIMES
> +	bool "Show non-zero printk timestamps early in boot"
> +	default n
> +	depends on PRINTK
> +	depends on ARM64 || X86_64
> +	help
> +	  Use a cycle-counter to provide printk timestamps during
> +	  early boot.  This allows seeing timestamps for printks that
> +	  would otherwise show as 0.  Note that this will shift the
> +	  printk timestamps to be relative to processor power on, instead
> +	  of relative to the start of kernel timekeeping.  This should be
> +	  closer to machine power on, giving a better indication of
> +	  overall boot time.
> +
>  config LOG_BUF_SHIFT
>  	int "Kernel log buffer size (16 => 64KB, 17 => 128KB)"
>  	range 12 25
> diff --git a/init/main.c b/init/main.c
> index b84818ad9685..d5774aec1aff 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -104,6 +104,7 @@
>  #include <linux/pidfs.h>
>  #include <linux/ptdump.h>
>  #include <linux/time_namespace.h>
> +#include <linux/early_times.h>
>  #include <net/net_namespace.h>
>  
>  #include <asm/io.h>
> @@ -1118,6 +1119,9 @@ void start_kernel(void)
>  	timekeeping_init();
>  	time_init();
>  
> +	/* This must be after timekeeping is initialized */
> +	early_times_start_calibration();
> +
>  	/* This must be after timekeeping is initialized */
>  	random_init();
>  
> @@ -1600,6 +1604,8 @@ static int __ref kernel_init(void *unused)
>  
>  	do_sysctl_args();
>  
> +	early_times_finish_calibration();
> +
>  	if (ramdisk_execute_command) {
>  		ret = run_init_process(ramdisk_execute_command);
>  		if (!ret)
> 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);

printk_get_next_message() calls info_print_ext_header() for an extended
console (/dev/kmsg and netcon_ext use this), whereas for
non-extended consoles, record_print_text() -> info_print_prefix() ->
print_time() is called. So, this adjustment should be made in
print_time() too, otherwise non-extended console users are gonna be
spooked with insane timestamps. This may explain the non-zero early
timestamps Petr saw in his serial console output [1].

An accessor can be implemented for (struct printk_info).ts_nsec, say
get_timestamp(), which can be called from both the places.

[1] https://lore.kernel.org/all/aYDPn2EJgJIWGDhM@pathway/

Thanks,
Shashank

On Tue 2026-03-10 04:25:33, Shashank Balaji wrote:
> Hi again,
> 
> On Tue, Feb 10, 2026 at 04:47:41PM -0700, Tim Bird wrote:
> > During early boot, printk timestamps are reported as zero before
> > kernel timekeeping starts (e.g. before time_init()).  This
> > hinders boot-time optimization efforts.  This period is about 400
> > milliseconds for many current desktop and embedded machines
> > running Linux.
> > 
> > Add support to save cycles during early boot, and output correct
> > timestamp values after timekeeping is initialized.  get_cycles()
> > is operational on arm64 and x86_64 from kernel start.  Add code
> > and variables to save calibration values used to later convert
> > cycle counts to time values in the early printks.  Add a config
> > to control the feature.
> > 
> > This yields non-zero timestamps for printks from the very start
> > of kernel execution.  The timestamps are relative to the start of
> > the architecture-specified counter used in get_cycles
> > (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> > 
> > All timestamps reflect time from processor power-on instead of
> > time from the kernel's timekeeping initialization.
> > 
> > Signed-off-by: Tim Bird <tim.bird@sony.com>
> 
> So if a console is read before the cycles -> timestamp conversion can
> happen, then they'll see 0. But reading from userspace will give the
> right timestamps.
> 
> Based on the previous discussions, to address this possible confusion,
> if changing the timestamp format, like adding '?', is a no-go because
> of concerns of breaking existing monitoring tools, what about appending
> something to the printk string after the timestamp? Hmm, no, that'll
> affect grep'ability _and_ may break monitoring tools. Or what about a
> pr_warn() early in boot to warn about the possible timestamp difference?

Or we could make it more obvious from the message in
early_times_finish_calibration(), see below.

> At the very least the possibility of this difference should be
> documented in the Kconfig description.

Yeah, it would be nice to mention this in the Kconfig description.

> > --- /dev/null
> > +++ b/include/linux/early_times.h
> > @@ -0,0 +1,85 @@
> > +static inline void early_times_finish_calibration(void)
> > +{
> > +	cycles_t end_cycles;
> > +	u64 end_ns;
> > +
> > +	/* set calibration data for early_printk_times */
> > +	end_cycles = get_cycles();
> > +	end_ns = local_clock();
> > +	clocks_calc_mult_shift(&early_mult, &early_shift,
> > +		mul_u64_u64_div_u64(end_cycles - start_cycles,
> > +			NSEC_PER_SEC, end_ns - start_ns),
> > +		NSEC_PER_SEC, 100);
> > +	early_ts_offset = mul_u64_u32_shr(start_cycles, early_mult, early_shift) - start_ns;
> > +
> > +	pr_debug("Early printk times: mult=%u, shift=%u, offset=%llu ns\n",
> > +		early_mult, early_shift, early_ts_offset);

We might make it more obvious that an offset will get added to the
existing timestamp since this point.

Also it has a "surprising" user visible effect so that it should
be pr_info() instead of pr_debug(). Note pr_debug() messages might be hidden.

A minimalist change would be:

	pr_info("Calibrated offset for early printk times: mult=%u, shift=%u, offset=%llu ns\n",
		early_mult, early_shift, early_ts_offset);

And/Or we might add one more line:

	pr_info("The time offset is added for existing and newly added printk messages since now!");


> > +}
> > +
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -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);
> 
> printk_get_next_message() calls info_print_ext_header() for an extended
> console (/dev/kmsg and netcon_ext use this), whereas for
> non-extended consoles, record_print_text() -> info_print_prefix() ->
> print_time() is called. So, this adjustment should be made in
> print_time() too, otherwise non-extended console users are gonna be
> spooked with insane timestamps.

The v3 patch already modifies print_time().

> This may explain the non-zero early
> timestamps Petr saw in his serial console output [1].

I am a bit confused now. There are three stages:

   1. Early messages where the cycles are stored.

      The serial console shows zero time stamp because
      it reads the messages _before the calibration_, e.g.

	[    0.000000] Linux version 6.19.0-rc7-default+ (pmladek@pathway) (gcc (SUSE Linux) 15.2.1 20251006, GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.45.0.20251103-2) #521 SMP PREEMPT_DYNAMIC Mon Feb  2 16:36:53 CET 2026
	[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-6.19.0-rc7-default+ root=UUID=587ae802-e330-4059-9b48-d5b845e1075a resume=/dev/disk/by-uuid/369c7453-3d16-409d-88b2-5de027891a12 mitigations=auto nosplash earlycon=uart8250,io,0x3f8,115200 console=ttyS0,115200 console=ttynull console=tty0 debug_non_panic_cpus=1 panic=10 ignore_loglevel log_buf_len=1M
	[    0.000000] BIOS-provided physical RAM map:
	[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
	[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved

      But "dmesg" shows some numbers because it reads the messages
      _after the calibration_:

	[    8.853613] Linux version 6.19.0-rc7-default+ (pmladek@pathway) (gcc (SUSE Linux) 15.2.1 20251006, GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.45.0.20251103-2) #521 SMP PREEMPT_DYNAMIC Mon Feb  2 16:36:53 CET 2026
	[    8.853617] Command line: BOOT_IMAGE=/boot/vmlinuz-6.19.0-rc7-default+ root=UUID=587ae802-e330-4059-9b48-d5b845e1075a resume=/dev/disk/by-uuid/369c7453-3d16-409d-88b2-5de027891a12 mitigations=auto nosplash earlycon=uart8250,io,0x3f8,115200 console=ttyS0,115200 console=ttynull console=tty0 debug_non_panic_cpus=1 panic=10 ignore_loglevel log_buf_len=1M
	[    8.865086] BIOS-provided physical RAM map:
	[    8.865087] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
	[    8.865089] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved


   2. Early messages added _after the timekeeping_ is initialized
      but _before the early cycles calibration_.

      They serial console prints them _without the offset_ because
      it reads them _before the calibration_, e.g.

	[    3.288049][    T1] Write protecting the kernel read-only data: 36864k
	[    3.298554][    T1] Freeing unused kernel image (text/rodata gap) memory: 1656K
	[    3.318942][    T1] Freeing unused kernel image (rodata/data gap) memory: 1540K

       But "dmesg" prints them _with the offset_ because it reads them
       _after the calibration_, e.g.

	[   12.179999] [    T1] Write protecting the kernel read-only data: 36864k
	[   12.190505] [    T1] Freeing unused kernel image (text/rodata gap) memory: 1656K
	[   12.210893] [    T1] Freeing unused kernel image (rodata/data gap) memory: 1540K


   3. Messages added after the calibration of the early cycles.

      They are printed with the offset by both serial console and
      dmesg, e.g.

	[   12.230014][    T1] Early printk times: mult=38775352, shift=27, offset=8891950261 ns
	[   12.246008][    T1] Run /init as init process
	[   12.254944][    T1]   with arguments:
	[   12.264341][    T1]     /init


> An accessor can be implemented for (struct printk_info).ts_nsec, say
> get_timestamp(), which can be called from both the places.

Yeah, a helper function for reading the timestamp might be a cleaner solution.

> [1] https://lore.kernel.org/all/aYDPn2EJgJIWGDhM@pathway/

Everything seems to be as expected there. The non-zero timestamps
on the serial console are from messages added after the timekeeping
was initialized.

Best Regards,
Petr

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

On Tue 2026-03-10 02:27:27, Shashank Balaji wrote:
> 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
> 60325c27d3cfq printk: Add execution context (task name/CPU) to printk_info
> 499f86de4f8c init/main: read bootconfig header with get_unaligned_le32()

Good to know.

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

Yup, great catch!

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

Hmm, we could not change it easily because it would break user space
tools for reading kernel crash dump.

Alternative solution would be usign an union.

	union {
		u64	ts_nsec;
		u64	ts_cycles;
	};

Best Regards,
Petr

On Tue 2026-02-10 16:47:41, Tim Bird wrote:
> During early boot, printk timestamps are reported as zero before
> kernel timekeeping starts (e.g. before time_init()).  This
> hinders boot-time optimization efforts.  This period is about 400
> milliseconds for many current desktop and embedded machines
> running Linux.
> 
> Add support to save cycles during early boot, and output correct
> timestamp values after timekeeping is initialized.  get_cycles()
> is operational on arm64 and x86_64 from kernel start.  Add code
> and variables to save calibration values used to later convert
> cycle counts to time values in the early printks.  Add a config
> to control the feature.
> 
> This yields non-zero timestamps for printks from the very start
> of kernel execution.  The timestamps are relative to the start of
> the architecture-specified counter used in get_cycles
> (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> 
> All timestamps reflect time from processor power-on instead of
> time from the kernel's timekeeping initialization.
> 
> Signed-off-by: Tim Bird <tim.bird@sony.com>

It looks good to me and seems to work fine. Feel free to use:

Reviewed-by: Petr Mladek <pmladek@suse.com>
Tested-by: Petr Mladek <pmladek@suse.com>

See a note below.

> --- a/init/main.c
> +++ b/init/main.c
> @@ -104,6 +104,7 @@
>  #include <linux/pidfs.h>
>  #include <linux/ptdump.h>
>  #include <linux/time_namespace.h>
> +#include <linux/early_times.h>

JFYI, I have tried this patch on top of the current Linus' tree (v7.0-rc2+)
and it conflicted with the commit 499f86de4f8c34e19 ("init/main: read
bootconfig header with get_unaligned_le32()") which added here:

 #include <linux/unaligned.h>

>  #include <net/net_namespace.h>
>  
>  #include <asm/io.h>

Best Regards,
Petr