Re: [PATCH] printk: add early_counter_ns routine for printk blind spot

[Petr Mladek <pmladek@suse.com>]

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