[PATCH v4 0/1] printk: fix zero-valued printk timestamps

[Tim Bird <tim.bird@sony.com>]

Some kernel messages emitted before kernel timekeeping is started
have a timestamp value of zero.  However, some platforms
have a cycle counter or timer register that is initialized
before the kernel starts (either in hardware or pre-kernel
firmware), and it can be accessed to provide uncalibrated
values before any other kernel initialization.  I refer
to this period where kernel timestamps are zero as the
printk timing "blind spot".

The following patch allows developers to set a config value
CONFIG_EARLY_CYCLES_KHZ, that will be used to provide
useful timestamps on early printk messages.
This calibration value is set as a static configuration
variable, since it must be available from the very first kernel
instruction.  Since this value is machine-specific, it cannot
be used in the .config for a generic distribution kernel.
The feature is presented here as something useful for
kernel developers working on boot-time optimization
(ie, as something that can be used temporarily during boot
time research and development work, and not necessarily
a runtime option for the average user).

Different platforms have different blind spot durations.
On an x86_64 platform, due to early tsc initialization, the
blind spot may be as small at 16 milliseconds.  On a
Raspberry Pi 4 board, it is approximately 180 milliseconds.
On a RISC V BeagleV Fire board, it can be up to 1700
milliseconds (1.7 seconds).  On some platforms, the blind spot
duration is a significant percentage of the time before user-space
initialization in the kernel (greater than 20%).

This feature uses a different mechanism to gather timestamp values.
When kernel timekeeping starts, the printk timestamps change
to a new timebase based on local_clock(), and timestamp values
reset to the baseline used for kernel timekeeping. This results in a
one-time discontinuity in timestamps between early printks and later
printks. The discontinuity should be obvious to humans, but could
possibly confuse tools.

Here is before and after dmesg output for a Raspberry PI 4 board:

before:
[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.000000] Linux version 7.0.0-rc3-v8+ (tbird@timdesk) (aarch64-linux-gnu-gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #5 SMP PREEMPT Wed Mar 11 18:30:18 MDT 2026
[    0.000000] KASLR enabled
[    0.000000] random: crng init done
[    0.000000] Machine model: Raspberry Pi 4 Model B Rev 1.5
[    0.000000] efi: UEFI not found.
...
[    0.000000] Root IRQ handler: gic_handle_irq
[    0.000000] GIC: Using split EOI/Deactivate mode
[    0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000] arch_timer: cp15 timer running at 54.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000161] Console: colour dummy device 80x25
[    0.000170] printk: legacy console [tty1] enabled

after:
[    0.002975] Booting Linux on physical CPU 0x0000000000 [0x410fd083]
[    0.002998] Linux version 7.0.0-rc6-v8+ (tbird@timdesk) (aarch64-linux-gnu-gcc (Ubuntu 13.3.0-6ubuntu2~24.04) 13.3.0, GNU ld (GNU Binutils for Ubuntu) 2.42) #20 SMP PREEMPT Fri Apr 10 11:57:48 MDT 2026
[    0.003002] KASLR enabled
[    0.003338] random: crng init done
[    0.003866] Machine model: Raspberry Pi 4 Model B Rev 1.5
[    0.004495] efi: UEFI not found.
...
[    0.183552] Root IRQ handler: gic_handle_irq
[    0.183561] GIC: Using split EOI/Deactivate mode
[    0.183699] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.183958] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0xc743ce346, max_idle_ns: 440795203123 ns
[    0.183952] arch_timer: cp15 timer running at 54.00MHz (phys).
[    0.000000] sched_clock: 56 bits at 54MHz, resolution 18ns, wraps every 4398046511102ns
[    0.000157] Console: colour dummy device 80x25
[    0.000165] printk: legacy console [tty1] enabled


Tim Bird (1):
  printk: fix zero-valued printk timestamps in early boot

 include/linux/early_times.h | 55 +++++++++++++++++++++++++++++++++++++
 init/Kconfig                | 30 ++++++++++++++++++++
 kernel/printk/printk.c      |  3 ++
 3 files changed, 88 insertions(+)
 create mode 100644 include/linux/early_times.h

-- 
2.43.0