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

Michael Kelley
2026-03-11T15:47:04Z

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
[ 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

Hyper-V provides a synthetic clocksource (two actually), and perhaps they
are the cause of the problem, though I haven't spent any time debugging.

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: +--------+------+-----------------------------+---------------+--------+-------------------+

The cloud-init lines don't show up in dmesg, so there's no problem there.

I will look into both issues further, but probably not today.

Michael

>
> Signed-off-by: Tim Bird <tim.bird@sony.com>
> ---
> V2->V3
> Default CONFIG option to 'n'
> Move more code from into early_times.h
> (reducing ifdefs in init/main.c)
> Use math64 helper routines
> Use cycles_t instead of u64 type
> Add #defines for EARLY_CYCLES_BIT and MASK
> Invert if logic in adjust_early_ts()
> (note: no change to 'depends on' in Kconfig entry)
>
> 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)
>
> include/linux/early_times.h | 85 +++++++++++++++++++++++++++++++++++++
> init/Kconfig | 14 ++++++
> init/main.c | 6 +++
> kernel/printk/printk.c | 18 +++++++-
> 4 files changed, 121 insertions(+), 2 deletions(-)
> create mode 100644 include/linux/early_times.h
>
> diff --git a/include/linux/early_times.h b/include/linux/early_times.h
> new file mode 100644
> index 000000000000..05388dcb8573
> --- /dev/null
> +++ b/include/linux/early_times.h
> @@ -0,0 +1,85 @@
> +/* SPDX-License-Identifier: GPL-2.0 */
> +
> +#ifndef _KERNEL_PRINTK_EARLY_TIMES_H
> +#define _KERNEL_PRINTK_EARLY_TIMES_H
> +
> +#include <linux/timex.h>
> +#include <linux/clocksource.h>
> +
> +/* use high bit of a u64 to indicate cycles instead of a timestamp */
> +#define EARLY_CYCLES_BIT BIT_ULL(63)
> +#define EARLY_CYCLES_MASK ~(BIT_ULL(63))
> +
> +#if defined(CONFIG_EARLY_PRINTK_TIMES)
> +extern cycles_t start_cycles;
> +extern u64 start_ns;
> +extern u32 early_mult, early_shift;
> +extern u64 early_ts_offset;
> +
> +static inline void early_times_start_calibration(void)
> +{
> + start_cycles = get_cycles();
> + start_ns = local_clock();
> +}
> +
> +static inline void early_times_finish_calibration(void)
> +{
> + cycles_t end_cycles;
> + u64 end_ns;
> +
> + /* set calibration data for early_printk_times */
> + end_cycles = get_cycles();
> + end_ns = local_clock();
> + clocks_calc_mult_shift(&early_mult, &early_shift,
> + mul_u64_u64_div_u64(end_cycles - start_cycles,
> + NSEC_PER_SEC, end_ns - start_ns),
> + NSEC_PER_SEC, 100);
> + early_ts_offset = mul_u64_u32_shr(start_cycles, early_mult, early_shift) -
> start_ns;
> +
> + pr_debug("Early printk times: mult=%u, shift=%u, offset=%llu ns\n",
> + early_mult, early_shift, early_ts_offset);
> +}
> +
> +static inline u64 early_cycles(void)
> +{
> + return (get_cycles() | EARLY_CYCLES_BIT);
> +}
> +
> +/*
> + * adjust_early_ts detects whether ts in is cycles or nanoseconds
> + * and converts it or adjusts it, taking into account the offset
> + * from cycle-counter start.
> + *
> + * Note that early_mult may be 0, but that's OK because
> + * we'll just multiply by 0 and return 0. This will
> + * only occur if we're outputting a printk message
> + * before the calibration of the early timestamp.
> + * Any output after user space start (eg. from dmesg or
> + * journalctl) will show correct values.
> + */
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> + if (likely(!(ts & EARLY_CYCLES_BIT)))
> + /* if timestamp is not in cycles, just add offset */
> + return ts + early_ts_offset;
> +
> + /* mask high bit and convert to nanoseconds */
> + return mul_u64_u32_shr(ts & EARLY_CYCLES_MASK, early_mult, early_shift);
> +}
> +
> +#else
> +# define early_times_start_calibration() do { } while (0)
> +# define early_times_finish_calibration() do { } while (0)
> +
> +static inline u64 early_cycles(void)
> +{
> + return 0;
> +}
> +
> +static inline u64 adjust_early_ts(u64 ts)
> +{
> + return ts;
> +}
> +#endif /* CONFIG_EARLY_PRINTK_TIMES */
> +
> +#endif /* _KERNEL_PRINTK_EARLY_TIMES_H */
> diff --git a/init/Kconfig b/init/Kconfig
> index fa79feb8fe57..a928c1efb09d 100644
> --- a/init/Kconfig
> +++ b/init/Kconfig
> @@ -777,6 +777,20 @@ 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_PRINTK_TIMES
> + bool "Show non-zero printk timestamps early in boot"
> + default n
> + depends on PRINTK
> + depends on ARM64 || X86_64
> + help
> + Use a cycle-counter to provide printk timestamps during
> + early boot. This allows seeing timestamps for printks that
> + would otherwise show as 0. Note that this will shift the
> + printk timestamps to be relative to processor power on, instead
> + of relative to the start of kernel timekeeping. This should be
> + closer to machine power on, giving a better indication of
> + overall boot time.
> +
> 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 b84818ad9685..d5774aec1aff 100644
> --- a/init/main.c
> +++ b/init/main.c
> @@ -104,6 +104,7 @@
> #include <linux/pidfs.h>
> #include <linux/ptdump.h>
> #include <linux/time_namespace.h>
> +#include <linux/early_times.h>
> #include <net/net_namespace.h>
>
> #include <asm/io.h>
> @@ -1118,6 +1119,9 @@ 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();
>
> @@ -1600,6 +1604,8 @@ static int __ref kernel_init(void *unused)
>
> do_sysctl_args();
>
> + early_times_finish_calibration();
> +
> 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 1d765ad242b8..5afd31c3345c 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -46,6 +46,7 @@
> #include <linux/ctype.h>
> #include <linux/uio.h>
> #include <linux/sched/clock.h>
> +#include <linux/early_times.h>
> #include <linux/sched/debug.h>
> #include <linux/sched/task_stack.h>
> #include <linux/panic.h>
> @@ -75,6 +76,13 @@ EXPORT_SYMBOL(ignore_console_lock_warning);
>
> EXPORT_TRACEPOINT_SYMBOL_GPL(console);
>
> +#ifdef CONFIG_EARLY_PRINTK_TIMES
> +cycles_t start_cycles;
> +u64 start_ns;
> +u32 early_mult, early_shift;
> +u64 early_ts_offset;
> +#endif
> +
> /*
> * Low level drivers may need that to know if they can schedule in
> * their unblank() callback or not. So let's export it.
> @@ -639,7 +647,7 @@ static void append_char(char **pp, char *e, char c)
> static ssize_t info_print_ext_header(char *buf, size_t size,
> struct printk_info *info)
> {
> - u64 ts_usec = info->ts_nsec;
> + u64 ts_usec = adjust_early_ts(info->ts_nsec);
> char caller[20];
> #ifdef CONFIG_PRINTK_CALLER
> u32 id = info->caller_id;
> @@ -1352,7 +1360,11 @@ static size_t print_syslog(unsigned int level, char *buf)
>
> static size_t print_time(u64 ts, char *buf)
> {
> - unsigned long rem_nsec = do_div(ts, 1000000000);
> + unsigned long rem_nsec;
> +
> + ts = adjust_early_ts(ts);
> +
> + rem_nsec = do_div(ts, 1000000000);
>
> return sprintf(buf, "[%5lu.%06lu]",
> (unsigned long)ts, rem_nsec / 1000);
> @@ -2242,6 +2254,8 @@ int vprintk_store(int facility, int level,
> * timestamp with respect to the caller.
> */
> ts_nsec = local_clock();
> + if (!ts_nsec)
> + ts_nsec = early_cycles();
>
> caller_id = printk_caller_id();
>
> --
> 2.43.0
>