From: Tim Bird <tim.bird@sony.com>

During early boot, printk timestamps are reported as zero,
which creates a blind spot in early boot timings.  This blind
spot hinders timing and optimization efforts for code that
executes before time_init(), which is when local_clock() is
initialized sufficiently to start returning non-zero timestamps.
This period is about 400 milliseconds for many current desktop
and embedded machines running Linux.

Add an early_counter_ns function that returns nanosecond
timestamps based on get_cycles().  get_cycles() is operational
on arm64 and x86_64 from kernel start.  Add some calibration
printks to allow setting configuration variables that are used
to convert cycle counts to nanoseconds (which are then used
in early printks).  Add CONFIG_EARLY_COUNTER_NS, as well as
some associated conversion variables, as new kernel config
variables.

After proper configuration, this yields non-zero timestamps for
printks from the very start of kernel execution.  The timestamps
are relative to the start of the architecture-specific counter
used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
This means that the time reported reflects time-from-power-on for
most embedded products.  This is also a useful data point for
boot-time optimization work.

Note that there is a discontinuity in the timestamp sequencing
when standard clocks are finally initialized in time_init().
The printk timestamps are thus not monotonically increasing
through the entire boot.

Signed-off-by: Tim Bird <tim.bird@sony.com>
---
 init/Kconfig           | 47 ++++++++++++++++++++++++++++++++++++++++++
 init/main.c            | 25 ++++++++++++++++++++++
 kernel/printk/printk.c | 15 ++++++++++++++
 3 files changed, 87 insertions(+)

diff --git a/init/Kconfig b/init/Kconfig
index cab3ad28ca49..5352567c43ed 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -770,6 +770,53 @@ 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_COUNTER_NS
+	bool "Use counter for early printk timestamps"
+	default y
+	depends on PRINTK
+	help
+	  Use a cycle-counter to provide printk timestamps during early
+	  boot.  This allows seeing timing information that would
+	  otherwise be displayed with 0-valued timestamps.
+
+	  In order for this to work, you need to specify values for
+	  EARLY_COUNTER_MULT and EARLY_COUNTER_SHIFT, used to convert
+	  from the cycle count to nanoseconds.
+
+config EARLY_COUNTER_MULT
+	int "Multiplier for early cycle counter"
+	depends on PRINTK && EARLY_COUNTER_NS
+	default 1
+	help
+	  This value specifies a multiplier to be used when converting
+	  cycle counts to nanoseconds.  The formula used is:
+		  ns = (cycles * mult) >> shift
+
+	  Use a multiplier that will bring the value of (cycles * mult)
+	  to near a power of two, that is greater than 1000.  The
+	  nanoseconds returned by this conversion are divided by 1000
+	  to be used as the printk timestamp counter (with resolution
+	  of microseconds).
+
+	  As an example, for a cycle-counter with a frequency of 200 Mhz,
+	  the multiplier would be: 10485760, and the shift would be 21.
+
+config EARLY_COUNTER_SHIFT
+	int "Shift value for early cycle counter"
+	range 0 63
+	depends on PRINTK && EARLY_COUNTER_NS
+	default 0
+	help
+	  This value specifies a shift value to be used when converting
+	  cycle counts to nanoseconds.  The formula used is:
+		  ns = (cycles * mult) >> shift
+
+	  Use a shift that will bring the result to a value
+	  in nanoseconds.
+
+	  As an example, for a cycle-counter with a frequency of 200 Mhz,
+	  the multiplier would be: 10485760, and the shift would be 21.
+
 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 07a3116811c5..587aaaad22d1 100644
--- a/init/main.c
+++ b/init/main.c
@@ -105,6 +105,8 @@
 #include <linux/ptdump.h>
 #include <linux/time_namespace.h>
 #include <net/net_namespace.h>
+#include <linux/timex.h>
+#include <linux/sched/clock.h>
 
 #include <asm/io.h>
 #include <asm/setup.h>
@@ -906,6 +908,8 @@ static void __init early_numa_node_init(void)
 #endif
 }
 
+static u64 start_cycles, start_ns;
+
 asmlinkage __visible __init __no_sanitize_address __noreturn __no_stack_protector
 void start_kernel(void)
 {
@@ -1023,6 +1027,10 @@ void start_kernel(void)
 	timekeeping_init();
 	time_init();
 
+	/* used to calibrate early_counter_ns */
+	start_cycles = get_cycles();
+	start_ns = local_clock();
+
 	/* This must be after timekeeping is initialized */
 	random_init();
 
@@ -1474,6 +1482,8 @@ void __weak free_initmem(void)
 static int __ref kernel_init(void *unused)
 {
 	int ret;
+	u64 end_cycles, end_ns;
+	u32 early_mult, early_shift;
 
 	/*
 	 * Wait until kthreadd is all set-up.
@@ -1505,6 +1515,21 @@ static int __ref kernel_init(void *unused)
 
 	do_sysctl_args();
 
+	/* show calibration data for early_counter_ns */
+	end_cycles = get_cycles();
+	end_ns = local_clock();
+	clocks_calc_mult_shift(&early_mult, &early_shift,
+		((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
+		NSEC_PER_SEC, 50);
+
+#ifdef CONFIG_EARLY_COUNTER_NS
+	pr_info("Early Counter: start_cycles=%llu, end_cycles=%llu, cycles=%llu\n",
+		start_cycles, end_cycles, (end_cycles - start_cycles));
+	pr_info("Early Counter: start_ns=%llu, end_ns=%llu, ns=%llu\n",
+		start_ns, end_ns, (end_ns - start_ns));
+	pr_info("Early Counter: MULT=%u, SHIFT=%u\n", early_mult, early_shift);
+#endif
+
 	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 5aee9ffb16b9..522dd24cd534 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2210,6 +2210,19 @@ static u16 printk_sprint(char *text, u16 size, int facility,
 	return text_len;
 }
 
+#ifdef CONFIG_EARLY_COUNTER_NS
+static inline u64 early_counter_ns(void)
+{
+	return ((u64)get_cycles() * CONFIG_EARLY_COUNTER_MULT)
+		>> CONFIG_EARLY_COUNTER_SHIFT;
+}
+#else
+static inline u64 early_counter_ns(void)
+{
+	return 0;
+}
+#endif
+
 __printf(4, 0)
 int vprintk_store(int facility, int level,
 		  const struct dev_printk_info *dev_info,
@@ -2239,6 +2252,8 @@ int vprintk_store(int facility, int level,
 	 * timestamp with respect to the caller.
 	 */
 	ts_nsec = local_clock();
+	if (!ts_nsec)
+		ts_nsec = early_counter_ns();
 
 	caller_id = printk_caller_id();
 
-- 
2.43.0

Hi Tim,

kernel test robot noticed the following build errors:

[auto build test ERROR on linus/master]
[also build test ERROR on v6.18-rc7]
[cannot apply to akpm-mm/mm-everything next-20251127]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-add-early_counter_ns-routine-for-printk-blind-spot/20251125-133242
base:   linus/master
patch link:    https://lore.kernel.org/r/39b09edb-8998-4ebd-a564-7d594434a981%40bird.org
patch subject: [PATCH] printk: add early_counter_ns routine for printk blind spot
config: i386-randconfig-2006-20250825 (https://download.01.org/0day-ci/archive/20251127/202511271051.yfp2O98B-lkp@intel.com/config)
compiler: gcc-14 (Debian 14.2.0-19) 14.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20251127/202511271051.yfp2O98B-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202511271051.yfp2O98B-lkp@intel.com/

All errors (new ones prefixed by >>):

   ld: init/main.o: in function `kernel_init':
>> init/main.c:1522:(.ref.text+0x201): undefined reference to `__udivdi3'


vim +1522 init/main.c

  1481	
  1482	static int __ref kernel_init(void *unused)
  1483	{
  1484		int ret;
  1485		u64 end_cycles, end_ns;
  1486		u32 early_mult, early_shift;
  1487	
  1488		/*
  1489		 * Wait until kthreadd is all set-up.
  1490		 */
  1491		wait_for_completion(&kthreadd_done);
  1492	
  1493		kernel_init_freeable();
  1494		/* need to finish all async __init code before freeing the memory */
  1495		async_synchronize_full();
  1496	
  1497		system_state = SYSTEM_FREEING_INITMEM;
  1498		kprobe_free_init_mem();
  1499		ftrace_free_init_mem();
  1500		kgdb_free_init_mem();
  1501		exit_boot_config();
  1502		free_initmem();
  1503		mark_readonly();
  1504	
  1505		/*
  1506		 * Kernel mappings are now finalized - update the userspace page-table
  1507		 * to finalize PTI.
  1508		 */
  1509		pti_finalize();
  1510	
  1511		system_state = SYSTEM_RUNNING;
  1512		numa_default_policy();
  1513	
  1514		rcu_end_inkernel_boot();
  1515	
  1516		do_sysctl_args();
  1517	
  1518		/* show calibration data for early_counter_ns */
  1519		end_cycles = get_cycles();
  1520		end_ns = local_clock();
  1521		clocks_calc_mult_shift(&early_mult, &early_shift,
> 1522			((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
  1523			NSEC_PER_SEC, 50);
  1524	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Adding some people from the time subsystem into Cc.
Please, keep them in the loop in the eventual next version of the
patch.

For the new people, please note the discussion has already started,
see
https://lore.kernel.org/r/39b09edb-8998-4ebd-a564-7d594434a981@bird.org

Best Regards,
Petr

On Mon 2025-11-24 22:30:52, Tim Bird wrote:
> From: Tim Bird <tim.bird@sony.com>
> 
> During early boot, printk timestamps are reported as zero,
> which creates a blind spot in early boot timings.  This blind
> spot hinders timing and optimization efforts for code that
> executes before time_init(), which is when local_clock() is
> initialized sufficiently to start returning non-zero timestamps.
> This period is about 400 milliseconds for many current desktop
> and embedded machines running Linux.
> 
> Add an early_counter_ns function that returns nanosecond
> timestamps based on get_cycles().  get_cycles() is operational
> on arm64 and x86_64 from kernel start.  Add some calibration
> printks to allow setting configuration variables that are used
> to convert cycle counts to nanoseconds (which are then used
> in early printks).  Add CONFIG_EARLY_COUNTER_NS, as well as
> some associated conversion variables, as new kernel config
> variables.
> 
> After proper configuration, this yields non-zero timestamps for
> printks from the very start of kernel execution.  The timestamps
> are relative to the start of the architecture-specific counter
> used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> This means that the time reported reflects time-from-power-on for
> most embedded products.  This is also a useful data point for
> boot-time optimization work.
> 
> Note that there is a discontinuity in the timestamp sequencing
> when standard clocks are finally initialized in time_init().
> The printk timestamps are thus not monotonically increasing
> through the entire boot.
> 
> Signed-off-by: Tim Bird <tim.bird@sony.com>
> ---
>  init/Kconfig           | 47 ++++++++++++++++++++++++++++++++++++++++++
>  init/main.c            | 25 ++++++++++++++++++++++
>  kernel/printk/printk.c | 15 ++++++++++++++
>  3 files changed, 87 insertions(+)
> 
> diff --git a/init/Kconfig b/init/Kconfig
> index cab3ad28ca49..5352567c43ed 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -770,6 +770,53 @@ 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_COUNTER_NS
> +	bool "Use counter for early printk timestamps"
> +	default y
> +	depends on PRINTK
> +	help
> +	  Use a cycle-counter to provide printk timestamps during early
> +	  boot.  This allows seeing timing information that would
> +	  otherwise be displayed with 0-valued timestamps.
> +
> +	  In order for this to work, you need to specify values for
> +	  EARLY_COUNTER_MULT and EARLY_COUNTER_SHIFT, used to convert
> +	  from the cycle count to nanoseconds.
> +
> +config EARLY_COUNTER_MULT
> +	int "Multiplier for early cycle counter"
> +	depends on PRINTK && EARLY_COUNTER_NS
> +	default 1
> +	help
> +	  This value specifies a multiplier to be used when converting
> +	  cycle counts to nanoseconds.  The formula used is:
> +		  ns = (cycles * mult) >> shift
> +
> +	  Use a multiplier that will bring the value of (cycles * mult)
> +	  to near a power of two, that is greater than 1000.  The
> +	  nanoseconds returned by this conversion are divided by 1000
> +	  to be used as the printk timestamp counter (with resolution
> +	  of microseconds).
> +
> +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> +	  the multiplier would be: 10485760, and the shift would be 21.
> +
> +config EARLY_COUNTER_SHIFT
> +	int "Shift value for early cycle counter"
> +	range 0 63
> +	depends on PRINTK && EARLY_COUNTER_NS
> +	default 0
> +	help
> +	  This value specifies a shift value to be used when converting
> +	  cycle counts to nanoseconds.  The formula used is:
> +		  ns = (cycles * mult) >> shift
> +
> +	  Use a shift that will bring the result to a value
> +	  in nanoseconds.
> +
> +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> +	  the multiplier would be: 10485760, and the shift would be 21.
> +
>  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 07a3116811c5..587aaaad22d1 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -105,6 +105,8 @@
>  #include <linux/ptdump.h>
>  #include <linux/time_namespace.h>
>  #include <net/net_namespace.h>
> +#include <linux/timex.h>
> +#include <linux/sched/clock.h>
>  
>  #include <asm/io.h>
>  #include <asm/setup.h>
> @@ -906,6 +908,8 @@ static void __init early_numa_node_init(void)
>  #endif
>  }
>  
> +static u64 start_cycles, start_ns;
> +
>  asmlinkage __visible __init __no_sanitize_address __noreturn __no_stack_protector
>  void start_kernel(void)
>  {
> @@ -1023,6 +1027,10 @@ void start_kernel(void)
>  	timekeeping_init();
>  	time_init();
>  
> +	/* used to calibrate early_counter_ns */
> +	start_cycles = get_cycles();
> +	start_ns = local_clock();
> +
>  	/* This must be after timekeeping is initialized */
>  	random_init();
>  
> @@ -1474,6 +1482,8 @@ void __weak free_initmem(void)
>  static int __ref kernel_init(void *unused)
>  {
>  	int ret;
> +	u64 end_cycles, end_ns;
> +	u32 early_mult, early_shift;
>  
>  	/*
>  	 * Wait until kthreadd is all set-up.
> @@ -1505,6 +1515,21 @@ static int __ref kernel_init(void *unused)
>  
>  	do_sysctl_args();
>  
> +	/* show calibration data for early_counter_ns */
> +	end_cycles = get_cycles();
> +	end_ns = local_clock();
> +	clocks_calc_mult_shift(&early_mult, &early_shift,
> +		((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
> +		NSEC_PER_SEC, 50);
> +
> +#ifdef CONFIG_EARLY_COUNTER_NS
> +	pr_info("Early Counter: start_cycles=%llu, end_cycles=%llu, cycles=%llu\n",
> +		start_cycles, end_cycles, (end_cycles - start_cycles));
> +	pr_info("Early Counter: start_ns=%llu, end_ns=%llu, ns=%llu\n",
> +		start_ns, end_ns, (end_ns - start_ns));
> +	pr_info("Early Counter: MULT=%u, SHIFT=%u\n", early_mult, early_shift);
> +#endif
> +
>  	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 5aee9ffb16b9..522dd24cd534 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2210,6 +2210,19 @@ static u16 printk_sprint(char *text, u16 size, int facility,
>  	return text_len;
>  }
>  
> +#ifdef CONFIG_EARLY_COUNTER_NS
> +static inline u64 early_counter_ns(void)
> +{
> +	return ((u64)get_cycles() * CONFIG_EARLY_COUNTER_MULT)
> +		>> CONFIG_EARLY_COUNTER_SHIFT;
> +}
> +#else
> +static inline u64 early_counter_ns(void)
> +{
> +	return 0;
> +}
> +#endif
> +
>  __printf(4, 0)
>  int vprintk_store(int facility, int level,
>  		  const struct dev_printk_info *dev_info,
> @@ -2239,6 +2252,8 @@ int vprintk_store(int facility, int level,
>  	 * timestamp with respect to the caller.
>  	 */
>  	ts_nsec = local_clock();
> +	if (!ts_nsec)
> +		ts_nsec = early_counter_ns();
>  
>  	caller_id = printk_caller_id();
>  
> -- 
> 2.43.0

Hi Tim,

I tested this on my i.MX93 FRDM (arm64) board and after a bit of
fiddling with the MULT/SHIFT values I got it working. It can be a very
valuable addition.

Some comments follow.

On Mon, Nov 24, 2025 at 10:30:52PM -0700, Tim Bird wrote:
> From: Tim Bird <tim.bird@sony.com>
> 
> During early boot, printk timestamps are reported as zero,
> which creates a blind spot in early boot timings.  This blind
> spot hinders timing and optimization efforts for code that
> executes before time_init(), which is when local_clock() is
> initialized sufficiently to start returning non-zero timestamps.
> This period is about 400 milliseconds for many current desktop
> and embedded machines running Linux.
> 
> Add an early_counter_ns function that returns nanosecond
> timestamps based on get_cycles().  get_cycles() is operational
> on arm64 and x86_64 from kernel start.  Add some calibration
> printks to allow setting configuration variables that are used
> to convert cycle counts to nanoseconds (which are then used
> in early printks).  Add CONFIG_EARLY_COUNTER_NS, as well as
> some associated conversion variables, as new kernel config
> variables.
> 
> After proper configuration, this yields non-zero timestamps for
> printks from the very start of kernel execution.  The timestamps
> are relative to the start of the architecture-specific counter
> used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> This means that the time reported reflects time-from-power-on for
> most embedded products.  This is also a useful data point for
> boot-time optimization work.
> 
> Note that there is a discontinuity in the timestamp sequencing
> when standard clocks are finally initialized in time_init().
> The printk timestamps are thus not monotonically increasing
> through the entire boot.

This is... not going to work, IMO, and might lead to breakages in
userspace tools (are printk timings a userspace API?).

I actually have a counter-proposal: the time obtained through cycle
evaluation is used as an offset to be added to the printk time after
time_init() is called. A (working, but maybe sub-optimal) patch to
obtain this is attached at the end.

> 
> Signed-off-by: Tim Bird <tim.bird@sony.com>
> ---
>  init/Kconfig           | 47 ++++++++++++++++++++++++++++++++++++++++++
>  init/main.c            | 25 ++++++++++++++++++++++
>  kernel/printk/printk.c | 15 ++++++++++++++
>  3 files changed, 87 insertions(+)
> 
> diff --git a/init/Kconfig b/init/Kconfig
> index cab3ad28ca49..5352567c43ed 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -770,6 +770,53 @@ 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_COUNTER_NS
> +	bool "Use counter for early printk timestamps"
> +	default y
> +	depends on PRINTK
> +	help
> +	  Use a cycle-counter to provide printk timestamps during early
> +	  boot.  This allows seeing timing information that would
> +	  otherwise be displayed with 0-valued timestamps.
> +
> +	  In order for this to work, you need to specify values for
> +	  EARLY_COUNTER_MULT and EARLY_COUNTER_SHIFT, used to convert
> +	  from the cycle count to nanoseconds.
> +
> +config EARLY_COUNTER_MULT
> +	int "Multiplier for early cycle counter"
> +	depends on PRINTK && EARLY_COUNTER_NS
> +	default 1
> +	help
> +	  This value specifies a multiplier to be used when converting
> +	  cycle counts to nanoseconds.  The formula used is:
> +		  ns = (cycles * mult) >> shift
> +
> +	  Use a multiplier that will bring the value of (cycles * mult)
> +	  to near a power of two, that is greater than 1000.  The
> +	  nanoseconds returned by this conversion are divided by 1000
> +	  to be used as the printk timestamp counter (with resolution
> +	  of microseconds).
> +
> +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> +	  the multiplier would be: 10485760, and the shift would be 21.
> +

If I got this correclty:

	EARLY_COUNTER_MULT = (10^9 / freq) << EARLY_COUNTER_SHIFT

where EARLY_COUNTER_SHIFT can be chosen at will, provided it is big
enough to survice the ns->us conversion but small enough not to overflow
the u64 container. 

> +config EARLY_COUNTER_SHIFT
> +	int "Shift value for early cycle counter"
> +	range 0 63
> +	depends on PRINTK && EARLY_COUNTER_NS
> +	default 0
> +	help
> +	  This value specifies a shift value to be used when converting
> +	  cycle counts to nanoseconds.  The formula used is:
> +		  ns = (cycles * mult) >> shift
> +
> +	  Use a shift that will bring the result to a value
> +	  in nanoseconds.
> +
> +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> +	  the multiplier would be: 10485760, and the shift would be 21.
> +
>  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 07a3116811c5..587aaaad22d1 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -105,6 +105,8 @@
>  #include <linux/ptdump.h>
>  #include <linux/time_namespace.h>
>  #include <net/net_namespace.h>
> +#include <linux/timex.h>
> +#include <linux/sched/clock.h>
>  
>  #include <asm/io.h>
>  #include <asm/setup.h>
> @@ -906,6 +908,8 @@ static void __init early_numa_node_init(void)
>  #endif
>  }
>  
> +static u64 start_cycles, start_ns;
> +
>  asmlinkage __visible __init __no_sanitize_address __noreturn __no_stack_protector
>  void start_kernel(void)
>  {
> @@ -1023,6 +1027,10 @@ void start_kernel(void)
>  	timekeeping_init();
>  	time_init();
>  
> +	/* used to calibrate early_counter_ns */
> +	start_cycles = get_cycles();
> +	start_ns = local_clock();
> +
>  	/* This must be after timekeeping is initialized */
>  	random_init();
>  
> @@ -1474,6 +1482,8 @@ void __weak free_initmem(void)
>  static int __ref kernel_init(void *unused)
>  {
>  	int ret;
> +	u64 end_cycles, end_ns;
> +	u32 early_mult, early_shift;
>  
>  	/*
>  	 * Wait until kthreadd is all set-up.
> @@ -1505,6 +1515,21 @@ static int __ref kernel_init(void *unused)
>  
>  	do_sysctl_args();
>  
> +	/* show calibration data for early_counter_ns */
> +	end_cycles = get_cycles();
> +	end_ns = local_clock();
> +	clocks_calc_mult_shift(&early_mult, &early_shift,
> +		((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
> +		NSEC_PER_SEC, 50);
> +
> +#ifdef CONFIG_EARLY_COUNTER_NS
> +	pr_info("Early Counter: start_cycles=%llu, end_cycles=%llu, cycles=%llu\n",
> +		start_cycles, end_cycles, (end_cycles - start_cycles));
> +	pr_info("Early Counter: start_ns=%llu, end_ns=%llu, ns=%llu\n",
> +		start_ns, end_ns, (end_ns - start_ns));
> +	pr_info("Early Counter: MULT=%u, SHIFT=%u\n", early_mult, early_shift);
> +#endif
> +

I don't get the need to have these here - should they be an help for the
integrator to calibrate and choose EARLY_COUNTER_MULT and
EARLY_COUNTER_SHIFT? The ns values printed here have some meaning only if
these two parameters are already set correctly in the first place -
what's the foreseen calibration procedure?

Moreover, if they are only required for calibration, maybe pr_debugi()
would be a better choice?

>  	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 5aee9ffb16b9..522dd24cd534 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2210,6 +2210,19 @@ static u16 printk_sprint(char *text, u16 size, int facility,
>  	return text_len;
>  }
>  
> +#ifdef CONFIG_EARLY_COUNTER_NS
> +static inline u64 early_counter_ns(void)
> +{
> +	return ((u64)get_cycles() * CONFIG_EARLY_COUNTER_MULT)
> +		>> CONFIG_EARLY_COUNTER_SHIFT;
> +}
> +#else
> +static inline u64 early_counter_ns(void)
> +{
> +	return 0;
> +}
> +#endif
> +
>  __printf(4, 0)
>  int vprintk_store(int facility, int level,
>  		  const struct dev_printk_info *dev_info,
> @@ -2239,6 +2252,8 @@ int vprintk_store(int facility, int level,
>  	 * timestamp with respect to the caller.
>  	 */
>  	ts_nsec = local_clock();
> +	if (!ts_nsec)
> +		ts_nsec = early_counter_ns();
>  
>  	caller_id = printk_caller_id();
>  
> -- 
> 2.43.0
> 
> 

Best regards,

Francesco

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 522dd24cd534..b4108f215c5e 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2216,11 +2216,26 @@ static inline u64 early_counter_ns(void)
 	return ((u64)get_cycles() * CONFIG_EARLY_COUNTER_MULT)
 		>> CONFIG_EARLY_COUNTER_SHIFT;
 }
+
+static u64 early_counter_ns_offset(void)
+{
+	static u64 early_counter_ns_start = 0;
+
+	if (!early_counter_ns_start)
+		early_counter_ns_start = early_counter_ns();
+
+	return early_counter_ns_start;
+}
 #else
 static inline u64 early_counter_ns(void)
 {
 	return 0;
 }
+
+static inline u64 early_counter_ns_offset(void)
+{
+	return 0;
+}
 #endif
 
 __printf(4, 0)
@@ -2254,6 +2269,8 @@ int vprintk_store(int facility, int level,
 	ts_nsec = local_clock();
 	if (!ts_nsec)
 		ts_nsec = early_counter_ns();
+	else
+		ts_nsec += early_counter_ns_offset();
 
 	caller_id = printk_caller_id();

On Tue 2025-11-25 14:08:40, Francesco Valla wrote:
> Hi Tim,
> 
> I tested this on my i.MX93 FRDM (arm64) board and after a bit of
> fiddling with the MULT/SHIFT values I got it working. It can be a very
> valuable addition.
> 
> Some comments follow.
> 
> On Mon, Nov 24, 2025 at 10:30:52PM -0700, Tim Bird wrote:
> > From: Tim Bird <tim.bird@sony.com>
> > 
> > During early boot, printk timestamps are reported as zero,
> > which creates a blind spot in early boot timings.  This blind
> > spot hinders timing and optimization efforts for code that
> > executes before time_init(), which is when local_clock() is
> > initialized sufficiently to start returning non-zero timestamps.
> > This period is about 400 milliseconds for many current desktop
> > and embedded machines running Linux.
> > 
> > Add an early_counter_ns function that returns nanosecond
> > timestamps based on get_cycles().  get_cycles() is operational
> > on arm64 and x86_64 from kernel start.  Add some calibration
> > printks to allow setting configuration variables that are used
> > to convert cycle counts to nanoseconds (which are then used
> > in early printks).  Add CONFIG_EARLY_COUNTER_NS, as well as
> > some associated conversion variables, as new kernel config
> > variables.
> > 
> > After proper configuration, this yields non-zero timestamps for
> > printks from the very start of kernel execution.  The timestamps
> > are relative to the start of the architecture-specific counter
> > used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> > This means that the time reported reflects time-from-power-on for
> > most embedded products.  This is also a useful data point for
> > boot-time optimization work.
> > 
> > Note that there is a discontinuity in the timestamp sequencing
> > when standard clocks are finally initialized in time_init().
> > The printk timestamps are thus not monotonically increasing
> > through the entire boot.
> 
> This is... not going to work, IMO, and might lead to breakages in
> userspace tools (are printk timings a userspace API?).

Honestly, I am not sure if it would break anything. The fact is
that printk() always used monotonic timers. And it is possible
that some userspace depends on it.

I personally thing that non-monotonic time stamps might be confusing
but they should not cause any serious breakage. But I might be wrong.
People are creative...

> I actually have a counter-proposal: the time obtained through cycle
> evaluation is used as an offset to be added to the printk time after
> time_init() is called. A (working, but maybe sub-optimal) patch to
> obtain this is attached at the end.

I am not sure if this is a good idea. The offset would cause
that all post-timer-init printk timestamps differ from values
provided by the timer API. And it might cause confusion,
for example, when they are printed as part of the message,
or when analyzing a crash dump.

On the other hand, there are various clock sources in the kernel
which are not comparable anyway. So maybe I am too cautious.

> > --- a/init/Kconfig
> > +++ b/init/Kconfig
> > @@ -770,6 +770,53 @@ 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_COUNTER_NS
> > +	bool "Use counter for early printk timestamps"
> > +	default y
> > +	depends on PRINTK
> > +	help
> > +	  Use a cycle-counter to provide printk timestamps during early
> > +	  boot.  This allows seeing timing information that would
> > +	  otherwise be displayed with 0-valued timestamps.
> > +
> > +	  In order for this to work, you need to specify values for
> > +	  EARLY_COUNTER_MULT and EARLY_COUNTER_SHIFT, used to convert
> > +	  from the cycle count to nanoseconds.
> > +
> > +config EARLY_COUNTER_MULT
> > +	int "Multiplier for early cycle counter"
> > +	depends on PRINTK && EARLY_COUNTER_NS
> > +	default 1
> > +	help
> > +	  This value specifies a multiplier to be used when converting
> > +	  cycle counts to nanoseconds.  The formula used is:
> > +		  ns = (cycles * mult) >> shift
> > +
> > +	  Use a multiplier that will bring the value of (cycles * mult)
> > +	  to near a power of two, that is greater than 1000.  The
> > +	  nanoseconds returned by this conversion are divided by 1000
> > +	  to be used as the printk timestamp counter (with resolution
> > +	  of microseconds).
> > +
> > +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> > +	  the multiplier would be: 10485760, and the shift would be 21.
> > +
> 
> If I got this correclty:
> 
> 	EARLY_COUNTER_MULT = (10^9 / freq) << EARLY_COUNTER_SHIFT
> 
> where EARLY_COUNTER_SHIFT can be chosen at will, provided it is big
> enough to survice the ns->us conversion but small enough not to overflow
> the u64 container. 
> 
> > +config EARLY_COUNTER_SHIFT
> > +	int "Shift value for early cycle counter"
> > +	range 0 63
> > +	depends on PRINTK && EARLY_COUNTER_NS
> > +	default 0
> > +	help
> > +	  This value specifies a shift value to be used when converting
> > +	  cycle counts to nanoseconds.  The formula used is:
> > +		  ns = (cycles * mult) >> shift
> > +
> > +	  Use a shift that will bring the result to a value
> > +	  in nanoseconds.
> > +
> > +	  As an example, for a cycle-counter with a frequency of 200 Mhz,
> > +	  the multiplier would be: 10485760, and the shift would be 21.
> > +
> >  config LOG_BUF_SHIFT
> >  	int "Kernel log buffer size (16 => 64KB, 17 => 128KB)"
> >  	range 12 25

So, it is usable only for a particular HW. It is not usable for a
generic kernel which is supposed to run on misc HW.

I guess that there is no way to detect the CPU frequency at runtime?

Best Regards,
Petr

Hi all,

On Wed, 26 Nov 2025 at 03:24, Francesco Valla <francesco@valla.it> wrote:
> On Mon, Nov 24, 2025 at 10:30:52PM -0700, Tim Bird wrote:
> > From: Tim Bird <tim.bird@sony.com>
> >
> > During early boot, printk timestamps are reported as zero,
> > which creates a blind spot in early boot timings.  This blind
> > spot hinders timing and optimization efforts for code that
> > executes before time_init(), which is when local_clock() is
> > initialized sufficiently to start returning non-zero timestamps.
> > This period is about 400 milliseconds for many current desktop
> > and embedded machines running Linux.
> >
> > Add an early_counter_ns function that returns nanosecond
> > timestamps based on get_cycles().  get_cycles() is operational
> > on arm64 and x86_64 from kernel start.  Add some calibration
> > printks to allow setting configuration variables that are used
> > to convert cycle counts to nanoseconds (which are then used
> > in early printks).  Add CONFIG_EARLY_COUNTER_NS, as well as
> > some associated conversion variables, as new kernel config
> > variables.
> >
> > After proper configuration, this yields non-zero timestamps for
> > printks from the very start of kernel execution.  The timestamps
> > are relative to the start of the architecture-specific counter
> > used in get_cycles (e.g. the TSC on x86_64 and cntvct_el0 on arm64).
> > This means that the time reported reflects time-from-power-on for
> > most embedded products.  This is also a useful data point for
> > boot-time optimization work.
> >
> > Note that there is a discontinuity in the timestamp sequencing
> > when standard clocks are finally initialized in time_init().
> > The printk timestamps are thus not monotonically increasing
> > through the entire boot.
>
> This is... not going to work, IMO, and might lead to breakages in
> userspace tools (are printk timings a userspace API?).

I think they are.

Another approach would be to defer the calibration/conversion to
userspace, and make sure the early part stands out.
I.e. when real timekeeping is available, kernel messages are prefixed by
"[%5lu.%06lu]".  Early messages could be prefixed by a plain integer
"[%12u]", containing the raw cycle counter value.
The presence of the decimal point would make the difference obvious.

> I actually have a counter-proposal: the time obtained through cycle
> evaluation is used as an offset to be added to the printk time after
> time_init() is called. A (working, but maybe sub-optimal) patch to
> obtain this is attached at the end.

Oh, that's a nice idea, too!

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Hi Tim,

kernel test robot noticed the following build errors:

[auto build test ERROR on linus/master]
[also build test ERROR on v6.18-rc7]
[cannot apply to akpm-mm/mm-everything next-20251124]
[If your patch is applied to the wrong git tree, kindly drop us a note.
And when submitting patch, we suggest to use '--base' as documented in
https://git-scm.com/docs/git-format-patch#_base_tree_information]

url:    https://github.com/intel-lab-lkp/linux/commits/Tim-Bird/printk-add-early_counter_ns-routine-for-printk-blind-spot/20251125-133242
base:   linus/master
patch link:    https://lore.kernel.org/r/39b09edb-8998-4ebd-a564-7d594434a981%40bird.org
patch subject: [PATCH] printk: add early_counter_ns routine for printk blind spot
config: powerpc-allnoconfig (https://download.01.org/0day-ci/archive/20251125/202511251534.9kMSsAH6-lkp@intel.com/config)
compiler: powerpc-linux-gcc (GCC) 15.1.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20251125/202511251534.9kMSsAH6-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202511251534.9kMSsAH6-lkp@intel.com/

All errors (new ones prefixed by >>):

   powerpc-linux-ld: init/main.o: in function `kernel_init':
>> main.c:(.ref.text+0x144): undefined reference to `__udivdi3'

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

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 power-on instead of time from
the kernel's timekeeping initialization.

Signed-off-by: Tim Bird <tim.bird@sony.com>
---
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 | 48 +++++++++++++++++++++++++++++++++++++
 init/Kconfig                | 12 ++++++++++
 init/main.c                 | 26 ++++++++++++++++++++
 kernel/printk/printk.c      | 16 +++++++++++--
 4 files changed, 100 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..9dc31eb442c2
--- /dev/null
+++ b/include/linux/early_times.h
@@ -0,0 +1,48 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
+#define _KERNEL_PRINTK_EARLY_TIMES_H
+
+#include <linux/timex.h>
+
+#if defined(CONFIG_EARLY_PRINTK_TIMES)
+extern u32 early_mult, early_shift;
+extern u64 early_ts_offset;
+
+static inline u64 early_cycles(void)
+{
+	return ((u64)get_cycles() | (1ULL << 63));
+}
+
+static inline u64 adjust_early_ts(u64 ts)
+{
+	/* High bit means ts is a cycle count */
+	if (unlikely(ts & (1ULL << 63)))
+		/*
+		 * mask high bit and convert to ns
+		 * 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.
+		 */
+		return (((ts & ~(1ULL << 63)) * early_mult) >> early_shift);
+
+	/* If timestamp is already in ns, just add offset */
+	return ts + early_ts_offset;
+}
+#else
+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..060a22cddd17 100644
--- a/init/Kconfig
+++ b/init/Kconfig
@@ -777,6 +777,18 @@ 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 y
+	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 machine power on, instead
+	  of relative to the start of kernel timekeeping.
+
 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..cc1af26933f7 100644
--- a/init/main.c
+++ b/init/main.c
@@ -104,6 +104,9 @@
 #include <linux/pidfs.h>
 #include <linux/ptdump.h>
 #include <linux/time_namespace.h>
+#include <linux/timex.h>
+#include <linux/sched/clock.h>
+#include <linux/early_times.h>
 #include <net/net_namespace.h>
 
 #include <asm/io.h>
@@ -160,6 +163,10 @@ static size_t initargs_offs;
 # define initargs_offs 0
 #endif
 
+#ifdef CONFIG_EARLY_PRINTK_TIMES
+static u64 start_cycles, start_ns;
+#endif
+
 static char *execute_command;
 static char *ramdisk_execute_command = "/init";
 
@@ -1118,6 +1125,11 @@ void start_kernel(void)
 	timekeeping_init();
 	time_init();
 
+#ifdef CONFIG_EARLY_PRINTK_TIMES
+	start_cycles = get_cycles();
+	start_ns = local_clock();
+#endif
+
 	/* This must be after timekeeping is initialized */
 	random_init();
 
@@ -1600,6 +1612,20 @@ static int __ref kernel_init(void *unused)
 
 	do_sysctl_args();
 
+#ifdef CONFIG_EARLY_PRINTK_TIMES
+	u64 end_cycles, 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,
+		((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
+		NSEC_PER_SEC, 50);
+	early_ts_offset = ((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);
+#endif
+
 	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..f17877337735 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,11 @@ EXPORT_SYMBOL(ignore_console_lock_warning);
 
 EXPORT_TRACEPOINT_SYMBOL_GPL(console);
 
+#ifdef CONFIG_EARLY_PRINTK_TIMES
+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 +645,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 +1358,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 +2252,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

Hi Tim,

On Sat, 24 Jan 2026 at 20:41, Tim Bird <tim.bird@sony.com> 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 power-on instead of time from
> the kernel's timekeeping initialization.
>
> Signed-off-by: Tim Bird <tim.bird@sony.com>
> ---
> 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)

Thanks for the update!

> --- /dev/null
> +++ b/include/linux/early_times.h
> @@ -0,0 +1,48 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
> +#define _KERNEL_PRINTK_EARLY_TIMES_H
> +
> +#include <linux/timex.h>
> +
> +#if defined(CONFIG_EARLY_PRINTK_TIMES)
> +extern u32 early_mult, early_shift;
> +extern u64 early_ts_offset;
> +
> +static inline u64 early_cycles(void)
> +{
> +       return ((u64)get_cycles() | (1ULL << 63));

No need to cast to u64, as the second operand of the OR is u64 anyway.
BIT_ULL(63)

I think it would be good to have a #define for this at the top.

> +}
> +
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> +       /* High bit means ts is a cycle count */
> +       if (unlikely(ts & (1ULL << 63)))
> +               /*
> +                * mask high bit and convert to ns
> +                * 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.
> +                */
> +               return (((ts & ~(1ULL << 63)) * early_mult) >> early_shift);

Please use the mul_u64_u32_shr() helper.

Please wrap this block in curly braces.
Alternatively, you can invert the logic:

    if (likely(!(ts & DEFINITION_FOR_1ULL_LSH63)))
            return ts + early_ts_offset;

> +
> +       /* If timestamp is already in ns, just add offset */
> +       return ts + early_ts_offset;
> +}
> +#else
> +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..060a22cddd17 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -777,6 +777,18 @@ 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 y
> +       depends on PRINTK
> +       depends on ARM64 || X86_64

So for now this is limited to (a few) 64-bit platforms...

> +       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 machine power on, instead
> +         of relative to the start of kernel timekeeping.
> +
>  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..cc1af26933f7 100644
> --- a/init/main.c
> +++ b/init/main.c

> @@ -160,6 +163,10 @@ static size_t initargs_offs;
>  # define initargs_offs 0
>  #endif
>
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +static u64 start_cycles, start_ns;

cycles_t start_cycles;

(cycles_t is unsigned long, i.e. either 32- or 64-bit).

> +#endif
> +
>  static char *execute_command;
>  static char *ramdisk_execute_command = "/init";
>
> @@ -1118,6 +1125,11 @@ void start_kernel(void)
>         timekeeping_init();
>         time_init();
>
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +       start_cycles = get_cycles();
> +       start_ns = local_clock();
> +#endif
> +
>         /* This must be after timekeeping is initialized */
>         random_init();
>
> @@ -1600,6 +1612,20 @@ static int __ref kernel_init(void *unused)
>
>         do_sysctl_args();
>
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +       u64 end_cycles, end_ns;

cycles_t end_cycles;

> +
> +       /* set calibration data for early_printk_times */
> +       end_cycles = get_cycles();
> +       end_ns = local_clock();
> +       clocks_calc_mult_shift(&early_mult, &early_shift,
> +               ((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
> +               NSEC_PER_SEC, 50);

mul_u64_u64_div_u64() is probably the best helper that is available
(there is no mul_ulong_u32_div_u64()).

> +       early_ts_offset = ((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);
> +#endif
> +
>         if (ramdisk_execute_command) {
>                 ret = run_init_process(ramdisk_execute_command);
>                 if (!ret)

Gr{oetje,eeting}s,

                        Geert

-- 
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Hi Tim,

I tested this both on X86_64 QEMU and on a i.MX93 (ARM64) and can
confirm it is working as expected. Auto-calc of calibration data is far
better than the configuration parameters in v1.

It is slightly confusing to see a time value printed to serial output
and another one inside kmsg, but that's a human thing and should not
confuse any tool.

Some notes follow.

On Sat, Jan 24, 2026 at 12:40:27PM -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 power-on instead of time from
> the kernel's timekeeping initialization.
> 
> Signed-off-by: Tim Bird <tim.bird@sony.com>
> ---
> 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 | 48 +++++++++++++++++++++++++++++++++++++
>  init/Kconfig                | 12 ++++++++++
>  init/main.c                 | 26 ++++++++++++++++++++
>  kernel/printk/printk.c      | 16 +++++++++++--
>  4 files changed, 100 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..9dc31eb442c2
> --- /dev/null
> +++ b/include/linux/early_times.h
> @@ -0,0 +1,48 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
> +#define _KERNEL_PRINTK_EARLY_TIMES_H
> +
> +#include <linux/timex.h>
> +
> +#if defined(CONFIG_EARLY_PRINTK_TIMES)
> +extern u32 early_mult, early_shift;
> +extern u64 early_ts_offset;
> +
> +static inline u64 early_cycles(void)
> +{
> +	return ((u64)get_cycles() | (1ULL << 63));
> +}
> +
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> +	/* High bit means ts is a cycle count */
> +	if (unlikely(ts & (1ULL << 63)))
> +		/*
> +		 * mask high bit and convert to ns
> +		 * 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.
> +		 */
> +		return (((ts & ~(1ULL << 63)) * early_mult) >> early_shift);
> +
> +	/* If timestamp is already in ns, just add offset */
> +	return ts + early_ts_offset;
> +}
> +#else
> +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..060a22cddd17 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -777,6 +777,18 @@ 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 y

Considering that this might have a significant impact on monitoring
mechanisms already in place (that e.g. expect a specific dmesg print to
have a maximum associated time value), please consider a N default here.

> +	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 machine power on, instead
> +	  of relative to the start of kernel timekeeping.
> +

To be precise, the timestamps will be relative to processor power on;
the machine might have some other processors that run before the Linux
one (this is the case for example of i.MX9 or AM62 SoCs) and will be
unaccounted for even by this mechanism.

>  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..cc1af26933f7 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -104,6 +104,9 @@
>  #include <linux/pidfs.h>
>  #include <linux/ptdump.h>
>  #include <linux/time_namespace.h>
> +#include <linux/timex.h>
> +#include <linux/sched/clock.h>
> +#include <linux/early_times.h>
>  #include <net/net_namespace.h>
>  
>  #include <asm/io.h>
> @@ -160,6 +163,10 @@ static size_t initargs_offs;
>  # define initargs_offs 0
>  #endif
>  
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +static u64 start_cycles, start_ns;
> +#endif
> +
>  static char *execute_command;
>  static char *ramdisk_execute_command = "/init";
>  
> @@ -1118,6 +1125,11 @@ void start_kernel(void)
>  	timekeeping_init();
>  	time_init();
>  
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +	start_cycles = get_cycles();
> +	start_ns = local_clock();
> +#endif
> +

I was wondering it it wouldn't make more sense to move this logic to its
own file, and have a plain call e.g. to early_times_init() here
(continue...)

>  	/* This must be after timekeeping is initialized */
>  	random_init();
>  
> @@ -1600,6 +1612,20 @@ static int __ref kernel_init(void *unused)
>  
>  	do_sysctl_args();
>  
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +	u64 end_cycles, 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,
> +		((end_cycles - start_cycles) * NSEC_PER_SEC)/(end_ns - start_ns),
> +		NSEC_PER_SEC, 50);
> +	early_ts_offset = ((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);
> +#endif
> +

(...continue) and to early_times_calc() or something like that here.

In this way, all related variables (i.e.: start_cycles, start_ns from
this file, but also early_mult, early_shift, and early_ts_offset from
kernel/printk/printk.c) can be confined to their own file and not add
noise here.

>  	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..f17877337735 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,11 @@ EXPORT_SYMBOL(ignore_console_lock_warning);
>  
>  EXPORT_TRACEPOINT_SYMBOL_GPL(console);
>  
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +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 +645,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 +1358,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 +2252,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
>

Regards,
Francesco