Re: [PATCH v3] printk: fix zero-valued printk timestamps in early boot

[Petr Mladek <pmladek@suse.com>]

Finally added timekeeping maintainers and John into Cc.
We should have added time since v1.

Anyway, you might see the entire history at
https://lore.kernel.org/all/39b09edb-8998-4ebd-a564-7d594434a981@bird.org/


On Fri 2026-03-13 04:52:40, Bird, Tim wrote:
> Hey Micheal,
> 
> This report is very interesting. 
> 
> Thanks very much for trying it out!
> 
> > -----Original Message-----
> > From: Michael Kelley <mhklinux@outlook.com>
> > Sent: Wednesday, March 11, 2026 9:47 AM
> > From: Tim Bird <tim.bird@sony.com> Sent: Tuesday, February 10, 2026 3:48 PM
> > >
> > > 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 processor power-on instead of
> > > time from the kernel's timekeeping initialization.
> > 
> > I tried this patch in linux-next20260302 kernel running as a guest VM
> > on a Hyper-V host. Two things:
> > 
> > 1) In the dmesg output, I'm seeing a place where the timestamps briefly go
> > backwards -- i.e., they are not monotonically increasing. Here's a snippet,
> > where there's a smaller timestamp immediately after the tsc is detected:
> > 
> > [   27.994891] SMBIOS 3.1.0 present.
> > [   27.994893] DMI: Microsoft Corporation Virtual Machine/Virtual Machine, BIOS Hyper-V UEFI Release v4.1 09/25/2025
> > [   27.994898] DMI: Memory slots populated: 2/2
> > [   27.995202] Hypervisor detected: Microsoft Hyper-V
> > [   27.995205] Hyper-V: privilege flags low 0xae7f, high 0x3b8030, ext 0x62, hints 0xa0e24, misc 0xe0bed7b2
> > [   27.995208] Hyper-V: Nested features: 0x0
> > [   27.995209] Hyper-V: LAPIC Timer Frequency: 0xc3500
> > [   27.995210] Hyper-V: Using hypercall for remote TLB flush
> > [   27.995216] clocksource: hyperv_clocksource_tsc_page: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns
> > [   27.995218] clocksource: hyperv_clocksource_msr: mask: 0xffffffffffffffff max_cycles: 0x24e6a1710, max_idle_ns: 440795202120 ns
> > [   27.995220] tsc: Detected 2918.401 MHz processor
> 
> I wonder if the tsc is getting fiddled with or virtualized somewhere in here, as part of clocksource initialization.
> I believe each clocksource in the kernel maintains it's own internal offset, and maybe the offset that is
> being used ends up being slightly different from the cycle-counter offset that the early_times feature uses.
> I'm just throwing out guesses.  It's about a 4ms delta, which is pretty big.
> 
> > [   27.991060] e820: update [mem 0x00000000-0x00000fff] System RAM ==> device reserved
> > [   27.991062] e820: remove [mem 0x000a0000-0x000fffff] System RAM
> > [   27.991064] last_pfn = 0x210000 max_arch_pfn = 0x400000000
> > [   27.991065] x86/PAT: PAT support disabled because CONFIG_X86_PAT is disabled in the kernel.
> > [   27.991066] x86/PAT: Configuration [0-7]: WB  WT  UC- UC  WB  WT  UC- UC

I wonder how the calibration of the cycles is precise. I wonder if
the problem might be that cycles were faster right after boot than
later during the calibration.

I added the following debug output on top of this patch:

diff --git a/include/linux/early_times.h b/include/linux/early_times.h
index 05388dcb8573..cdb467345bcc 100644
--- a/include/linux/early_times.h
+++ b/include/linux/early_times.h
@@ -20,6 +20,7 @@ static inline void early_times_start_calibration(void)
 {
 	start_cycles = get_cycles();
 	start_ns = local_clock();
+	pr_info("Early printk times: started callibration: %llu ns\n", start_ns);
 }
 
 static inline void early_times_finish_calibration(void)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 774ffb1fa5ac..836cb03aaa6d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2308,6 +2308,8 @@ int vprintk_store(int facility, int level,
 	ts_nsec = local_clock();
 	if (!ts_nsec)
 		ts_nsec = early_cycles();
+	else
+		pr_info_once("local_clock() returned non-zero timestamp: %llu nsec\n", ts_nsec);
 
 	caller_id = printk_caller_id();
 

And it produced in my kvm:

Let's say that start of the cycle counter is

Start of stage A

[    8.684438] Linux version 7.0.0-rc2-default+ (pmladek@pathway) (gcc (SUSE Linux) 15.2.1 20260202, GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.45.0.20251103-2) #571 SMP PREEMPT_DYNAMIC Fri Mar 13 10:23:54 CET 2026
[    8.684442] Command line: BOOT_IMAGE=/boot/vmlinuz-7.0.0-rc2-default+ root=/dev/vda2 resume=/dev/disk/by-uuid/369c7453-3d16-409d-88b2-5de027891a12 mitigations=auto nosplash earlycon=uart8250,io,0x3f8,115200 console=ttyS0,115200 console=tty0 ignore_loglevel log_buf_len=1M crashkernel=512M,high crashkernel=72M,low
[...]
[    8.696633] earlycon: uart8250 at I/O port 0x3f8 (options '115200')
[    8.696639] printk: legacy bootconsole [uart8250] enabled
[    8.731303] printk: debug: ignoring loglevel setting.
[    8.732349] NX (Execute Disable) protection: active
[    8.733447] APIC: Static calls initialized
[    8.734667] SMBIOS 2.8 present.
[    8.735358] DMI: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.17.0-2-g4f253b9b-prebuilt.qemu.org 04/01/2014
[    8.737285] DMI: Memory slots populated: 1/1
[    8.738380] Hypervisor detected: KVM
[    8.739151] last_pfn = 0x7ffdc max_arch_pfn = 0x400000000
[    8.740254] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    8.732971] printk: local_clock() returned non-zero timestamp: 3486 nsec

End of stage A

This is the point where printk() started storing the values from
local_clock() instead of cycles.

Start of stage B

[    8.732971] kvm-clock: using sched offset of 252367014082295 cycles
[    8.735471] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    8.738880] tsc: Detected 3293.776 MHz processor
[    8.740474] e820: update [mem 0x00000000-0x00000fff] System RAM ==> device reserved
[...]
[    8.932671] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    8.934047] Early printk times: started callibration: 201079507 ns

End of stage B

This is where we started calibration of early cycles.

Start of stage C

[    8.935571] Console: colour dummy device 80x25
[...]
[    9.289673] thermal_sys: Registered thermal governor 'fair_share'
[    9.290077] thermal_sys: Registered thermal governor 'bang_bang'
[    9.292290] thermal_sys: Registered thermal governor 'step_wise'
[    9.293530] thermal_sys: Registered thermal governor 'user_space'
[    9.294856] cpuidle: using governor ladder
[    9.296302] cpuidle: using governor menu

Here the thermal governors are registered. I guess that they might
reduce speed of some HW.

[...]
[   11.974147] clk: Disabling unused clocks

Some unused clocks are disabled. I wonder if this might affect
counting the cycles.

[   12.330852] Freeing unused kernel image (rodata/data gap) memory: 1500K
[   12.351191] Early printk times: mult=19634245, shift=26, offset=8732967929 ns

End of stage C

Here is the end on calibration.

Now, if the frequence of the cycles was:

   + was higher in the stage A when only cycles were stored
   + was lower in stage C when it was calibrated against local_clock()

Then it might result in higher (calibrated) timestamps in stage A
and step back in stage B.

Or something like this. It is possible that even local_clock() does
not have a stable frequence during the early boot.

Idea: A solution might be to start calibration when printk()
      gets first non-zero time from local_clock.

      Something like:

diff --git a/include/linux/early_times.h b/include/linux/early_times.h
index 05388dcb8573..09d278996184 100644
--- a/include/linux/early_times.h
+++ b/include/linux/early_times.h
@@ -16,10 +16,13 @@ extern u64 start_ns;
 extern u32 early_mult, early_shift;
 extern u64 early_ts_offset;
 
-static inline void early_times_start_calibration(void)
+static inline void early_times_may_start_calibration(u64 ts_ns)
 {
+	if (start_ns)
+		return;
+
+	start_ns = ts_ns;
 	start_cycles = get_cycles();
-	start_ns = local_clock();
 }
 
 static inline void early_times_finish_calibration(void)
diff --git a/init/main.c b/init/main.c
index 27835270dfb5..a333b0da69cf 100644
--- a/init/main.c
+++ b/init/main.c
@@ -1123,9 +1123,6 @@ void start_kernel(void)
 	timekeeping_init();
 	time_init();
 
-	/* This must be after timekeeping is initialized */
-	early_times_start_calibration();
-
 	/* This must be after timekeeping is initialized */
 	random_init();
 
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 774ffb1fa5ac..19330b6b4eb2 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2306,7 +2306,9 @@ int vprintk_store(int facility, int level,
 	 * timestamp with respect to the caller.
 	 */
 	ts_nsec = local_clock();
-	if (!ts_nsec)
+	if (ts_nsec)
+		early_times_may_start_calibration(ts_nsec);
+	else
 		ts_nsec = early_cycles();
 
 	caller_id = printk_caller_id();


> > 
> > 2) A Linux VM running in the Azure cloud is also running on Hyper-V. Such a
> > VM typically uses cloud-init to set everything up at boot time, and cloud-init
> > is outputting lines to the serial console with a timestamp that looks like the
> > printk() timestamp, but apparently is not adjusted for the early timestamping
> > that this patch adds. Again, I haven't debugged what's going on -- I'm not
> > immediately sure of the mechanism that cloud-init uses to do output to the
> > serial console. The use of the Hyper-V synthetic clock source might the cause
> > of the problem here as well. Here's an output snippet from the serial console:
> > 
> > [   20.330414] systemd[1]: Condition check resulted in OpenVSwitch configuration for cleanup being skipped.
> > [   20.332911] systemd[1]: Condition check resulted in Set Up Additional Binary Formats being skipped.
> > [   20.333257] pstore: Registered efi_pstore as persistent store backend
> > [   20.334360] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
> > [   20.338319] systemd[1]: Starting Load Kernel Modules...
> > [   20.341094] systemd[1]: Starting Remount Root and Kernel File Systems...
> > [   20.350993] systemd[1]: Starting udev Coldplug all Devices...
> > [   20.356255] systemd[1]: Starting Uncomplicated firewall...
> > [   20.361536] systemd[1]: Started Journal Service.
> > [   20.386902] EXT4-fs (sda1): re-mounted c02dce0c-0c40-4e6e-88af-c5a0987b0adb r/w.
> > [   22.532033] /dev/sr0: Can't lookup blockdev
> > [    7.955973] cloud-init[783]: Cloud-init v. 24.3.1-0ubuntu0~20.04.1 running 'init-local' at Wed, 11 Mar 2026 15:27:06 +0000. Up 7.48
> > seconds.
> > [    9.933120] cloud-init[822]: Cloud-init v. 24.3.1-0ubuntu0~20.04.1 running 'init' at Wed, 11 Mar 2026 15:27:08 +0000. Up 9.82 seconds.
> > [    9.935483] cloud-init[822]: ci-info: ++++++++++++++++++++++++++++++++++++++Net device
> > info+++++++++++++++++++++++++++++++++++++++
> > [    9.937726] cloud-init[822]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+
> > [    9.939905] cloud-init[822]: ci-info: | Device |  Up  |           Address           |      Mask     | Scope  |     Hw-Address    |
> > [    9.942059] cloud-init[822]: ci-info: +--------+------+-----------------------------+---------------+--------+-------------------+

This is more complicated. I wonder if the timestamps from cloud-init()
are somehow synchronized with local_clock().

We might need to synchronize local_clock() with the cycles as well.
But there is the chicken&egg problem. We need:

    + to know the offset caused by cycles when local_clock() gets initialized.
    + local_clock() running for some time to calibrate cycles.

Hmm, I see that time-management people are not in Cc. We should have
added them since v1.

I add them now. Better late than never.

Best Regards,
Petr