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

Francesco Valla
2025-11-26T02:24:23Z

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();