Re: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot

[Roberto A. Foglietta]

On Wed, 15 Apr 2026 at 20:41, Geert Uytterhoeven <geert@xxxxxxxxxxxxxx> wrote:
>
> Hi Roberto,
...
> Thanks for your patch!
>
> > --- /dev/null
> > +++ kernel/printk/early_times.h
> > @@ -0,0 +1,26 @@
> > +/* SPDX-License-Identifier: GPL-2.0 */
> > +
> > +#ifndef _EARLY_TIMES_H
> > +#define _EARLY_TIMES_H
> > +
> > +#include <linux/timekeeping.h>
> > +
> > +/*
> > + * Fencing isn't optional here, otherwise unreliable values displaying
> > + */
> > +#if defined(CONFIG_ARM64)
> > +             #include <asm/sysreg.h>
> > +             #define __early_raw_cycles ({ u64 val; \
> > +                 asm volatile("isb; mrs %0, cntvct_el0" : "=r"(val)); val; })
> > +#elif defined(CONFIG_X86_64)
> > +             #define __early_raw_cycles ({ u64 val; \
> > +                 asm volatile("lfence; rdtsc; shl $32, %%rdx; or %%rdx, %%rax" \
> > +                     : "=a"(val) : : "rdx"); val; })
> > +#elif defined(CONFIG_RISCV_TIMER)
> > +             #define __early_raw_cycles ({ u64 val; \
> > +                 asm volatile("fence; rdtime %0" : "=r"(val)); val; })
> > +#else
>
> All of these should be handled in arch/*/include/asm/early_times.h...
>
> > +             #define __early_raw_cycles 0
>
> ... while this should be in include/asm-generic/early_times.h.

In the last release of the patch, I decided to stick with the "single
point of hacking" approach

https://github.com/robang74/uchaosys/blob/v069/cnfg/printk-early-boot-timestamps-hack-v5.patch

and I developed it in a way that can be proposed in such "exceptional
way" for this very specific case:

+#if CONFIG_PRINTK_EARLY_BOOT_TIMINGS
+#include "early_times.h"
+ /*
+ * Very few developers are using this feature and they're expecting to deal
+ * with it as a single point of change hack to be further customised by them.
+ */
+ if (unlikely(!ts_nsec))
+ ts_nsec = __early_raw_cycles;
+#endif

As you can see the include uses double quotes to indicate that the
header is local and it is not supposed to belong to the formal three:
it is where everyone of us will put it when we are going to do dirty
tricks to reach somewhat result, in the same folder of the printk.c,
out-of-the-three.

Why is this a very special case?

- First of all because just a variable is provided by the macros set.
No hypothesis, just a variable as-is because most of the few users
that might be interested in are going to watch HOW the relative
sequences of events are happening. Moreover, there is no reason to
pretend (sell) a timestamp when the timestamp sub-system is not ready
to provide that feature: fairness first, by clarity. Previously the
time skew was from zeros and something, now from two different ways of
tagging the printk.

- Second, because there is a very limited use of it due to almost
immediate timestamp readiness. Therefore those who are interested,
they were hacking with very LOW level stuff (or BIOS for those are
constraint but that evilness in x86 arch). For those people the ASM
code is fine and it is very useful to have it in the same place. And
it is in the interest of those who maintain the kernel that those
people have a single point of hack for the major arch available.
Easier is for them to test different arches, far more improbable an
under-tested patch will reach a proposal upstream stage... and trust
me about "under-tested" because I am an expert on that field... ;-)
LOL

- Third, because every assumption has been removed, even the basics
>>10 shifts. Just something that appears as a variable emerging from a
local header and these two things together should ring some bells in
the head of those who have a little experience of firmware / embedded.
Few constructs are more vicious than macros that resemble variables...
;-)

> > +             if (unlikely(!ts_nsec))
> > +                     ts_nsec = __early_raw_cycles >> 10;
>
> As there can be lots of variation in the granularity of early timers,
> I think the shift should be moved in the arch-specific __early_raw_cycles,
> so it is only done when useful.
>

I am attaching the matured V5 patch that I tested against the 5.15.202
LTS kernel. Please, sit on the approach -- include"local-stuff.h" --
and let your judgement get soothed by time and PoVs. For sure one
change is probably a necessity, moving the Kconfig part into the DEBUG
section from the INIT where it stays by now. However, moving a feature
around the menuconfig is the last and less effort change in a TODO
list.

For sake of completeness, I am attaching the V5 matured patch. Will it
be refused because of its approach? Fine, at least the idea of that
approach has a patch that can be applied to something and people can
give it a try. Which add a practical degree of judgemental because
usually we are attracted by the beauty of perfection and purity,
something that Franco Battiato entitled "Inneres Auge" (a call from
above) but as complementary we are also keen to fall in love for those
bare-simple dirty-practical solution... in the same sense that song
was intending with a convoluted and educated paraphrase... LOL

Cheers, R-
This is a heavily "refactored by hands" patch for Linux Kernel 5.15.202 LTS
trying to solve the source tree janitoring vs 1-single place hack for hackers
in need for a simple-bare profiling tool and based on the patch V4 submitted by

From: Tim Bird <tim.bird@xxxxxxxx>
Subject: [PATCH v4 1/1] printk: fix zero-valued printk timestamps in early boot
Date: Fri, 10 Apr 2026 14:37:41 -0600
Message-ID: <20260410203741.997410-2-tim.bird@xxxxxxxx>

During early boot, printk timestamps are reported as zero before
kernel timekeeping starts (i.e. before time_init()). This hinders
boot-time optimization efforts. This period ranges from 17 to 1700
milliseconds on different embedded machines running Linux.

Add support for early timestamps based on processor cycle-generators
that need no kernel initialization.This feature isn't intended for a 
generic distro kernels but for temporary use during kernel development
and boot-time research and optimization by kernel hackers only.

This yields non-zero timestamps for printks from the very start
of kernel execution. The timestamps are relative to the start of
an architecture-specific counter (e.g. tsc on x86_64 and cntvct_el0
on arm64). Affected timestamps reflect cycle counter related values
since init (usually machine power-on or virtual machine start) instead
of time from the kernel's timekeeping initialization. This results in
a discontinuity in the printk timestamp values, one time, when
kernel timekeeping starts.

Signed-off-by: Tim Bird <tim.bird@xxxxxxxx>
Signed-off-by: Roberto A. Foglietta <roberto.foglietta@xxxxxxxxx>
---
V5 -> V4
  Rationale: single point of change hack for printk. Code rewritten, entirely.
  It provides a feature for kernel hackers willing to profiling the early boot
  with a basic printk approach (rather than using HW monitors which might not
  be available or immediately available). Thus, it is a first-look or a last
  resort hack profiling feature. Something that isn't good to spread around
  the kernel sources tree and it is fine to have into a single header file.
V3 -> V4
  Replace config vars with single one: CONFIG_EARLY_CYCLES_KHZ
  Replace runtime calibration with static config variable
  Remove reference to get_cycles()
  Add support for RISCV platforms
V2 -> V3
  Default CONFIG option to 'n'
  Move more code into early_times.h (reduce ifdefs in init/main.c)
  Use match64 helper routines
  Use cycles_t instead of u64 type
  Add #defines for EARLY_CYCLES_BIT and EARLY_CYCLES_MASK
  Invert if logic in adjust_early_ts()
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

--- a/init/Kconfig	2026-04-15 11:34:05.823433712 +0200
+++ b/init/Kconfig	2026-04-15 11:36:12.703334604 +0200
@@ -833,6 +833,27 @@ config PRINTK_INDEX
 
 	  There is no additional runtime cost to printk with this enabled.
 
+config PRINTK_EARLY_BOOT_TIMINGS
+	bool "Early boot printk shows times in raw cycle counter style"
+	default 0
+	depends on PRINTK
+	depends on ARM64 || X86_64 || RISCV_TIMER
+	select PRINTK_TIME
+	help
+	  Boolean value, disabled by default.
+
+	  Set this to provide cycles information for printks in early boot
+	  (before the start of kernel timekeeping), that would otherwise
+	  show as 0. Profiling by relative monotonic values, not time.
+
+	  Note that this causes the kernel to show, for some early printks,
+	  cycles that are relative to processor power on, instead of
+	  relative to the start of kernel timekeeping. When kernel
+	  timekeeping starts, the timestamps values reset, causing
+	  a discontinuity in the timestamp values.
+
+	  If unsure, keep it disabled as per its default.
+
 #
 # Architectures with an unreliable sched_clock() should select this:
 #
--- /dev/null	2026-04-10 15:35:49.659741644 +0200
+++ b/kernel/printk/early_times.h	2026-04-15 11:32:49.786728602 +0200
@@ -0,0 +1,26 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _EARLY_TIMES_H
+#define _EARLY_TIMES_H
+
+#include <linux/timekeeping.h>
+
+/*
+ * Fencing isn't optional here, otherwise unreliable values displaying
+ */
+#if defined(CONFIG_ARM64)
+	#include <asm/sysreg.h>
+	#define __early_raw_cycles ({ u64 val; \
+		asm volatile("isb; mrs %0, cntvct_el0" : "=r"(val)); val; })
+#elif defined(CONFIG_X86_64)
+	#define __early_raw_cycles ({ u64 val; \
+		asm volatile("lfence; rdtsc; shl $32, %%rdx; or %%rdx, %%rax" \
+			: "=a"(val) : : "rdx"); val; })
+#elif defined(CONFIG_RISCV_TIMER)
+	#define __early_raw_cycles ({ u64 val; \
+		asm volatile("fence; rdtime %0" : "=r"(val)); val; })
+#else
+	#define __early_raw_cycles 0
+#endif
+
+#endif /* _EARLY_TIMES_H */
--- a/kernel/printk/printk.c	2026-04-15 11:39:55.372066802 +0200
+++ b/kernel/printk/printk.c	2026-04-15 11:39:33.458953582 +0200
@@ -2151,6 +2151,16 @@ int vprintk_store(int facility, int leve
 	 */
 	ts_nsec = local_clock();
 
+#if CONFIG_PRINTK_EARLY_BOOT_TIMINGS
+#include "early_times.h"
+	/*
+	 * Very few developers are using this feature and they're expecting to deal
+	 * with it as a single point of change hack to be further customised by them.
+	 */
+	if (unlikely(!ts_nsec))
+		ts_nsec = __early_raw_cycles;
+#endif
+
 	if (!printk_enter_irqsave(recursion_ptr, irqflags))
 		return 0;