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

Petr Mladek
2026-03-10T11:40:02Z

On Tue 2026-03-10 04:25:33, Shashank Balaji wrote:
> Hi again,
>
> On Tue, Feb 10, 2026 at 04:47:41PM -0700, Tim Bird wrote:
> > 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.
> >
> > Signed-off-by: Tim Bird <tim.bird@sony.com>
>
> So if a console is read before the cycles -> timestamp conversion can
> happen, then they'll see 0. But reading from userspace will give the
> right timestamps.
>
> Based on the previous discussions, to address this possible confusion,
> if changing the timestamp format, like adding '?', is a no-go because
> of concerns of breaking existing monitoring tools, what about appending
> something to the printk string after the timestamp? Hmm, no, that'll
> affect grep'ability _and_ may break monitoring tools. Or what about a
> pr_warn() early in boot to warn about the possible timestamp difference?

Or we could make it more obvious from the message in
early_times_finish_calibration(), see below.

> At the very least the possibility of this difference should be
> documented in the Kconfig description.

Yeah, it would be nice to mention this in the Kconfig description.

> > --- /dev/null
> > +++ b/include/linux/early_times.h
> > @@ -0,0 +1,85 @@
> > +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);

We might make it more obvious that an offset will get added to the
existing timestamp since this point.

Also it has a "surprising" user visible effect so that it should
be pr_info() instead of pr_debug(). Note pr_debug() messages might be hidden.

A minimalist change would be:

pr_info("Calibrated offset for early printk times: mult=%u, shift=%u, offset=%llu ns\n",
early_mult, early_shift, early_ts_offset);

And/Or we might add one more line:

pr_info("The time offset is added for existing and newly added printk messages since now!");

> > +}
> > +
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -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);
>
> printk_get_next_message() calls info_print_ext_header() for an extended
> console (/dev/kmsg and netcon_ext use this), whereas for
> non-extended consoles, record_print_text() -> info_print_prefix() ->
> print_time() is called. So, this adjustment should be made in
> print_time() too, otherwise non-extended console users are gonna be
> spooked with insane timestamps.

The v3 patch already modifies print_time().

> This may explain the non-zero early
> timestamps Petr saw in his serial console output [1].

I am a bit confused now. There are three stages:

1. Early messages where the cycles are stored.

The serial console shows zero time stamp because
it reads the messages _before the calibration_, e.g.

[ 0.000000] Linux version 6.19.0-rc7-default+ (pmladek@pathway) (gcc (SUSE Linux) 15.2.1 20251006, GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.45.0.20251103-2) #521 SMP PREEMPT_DYNAMIC Mon Feb 2 16:36:53 CET 2026
[ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-6.19.0-rc7-default+ root=UUID=587ae802-e330-4059-9b48-d5b845e1075a resume=/dev/disk/by-uuid/369c7453-3d16-409d-88b2-5de027891a12 mitigations=auto nosplash earlycon=uart8250,io,0x3f8,115200 console=ttyS0,115200 console=ttynull console=tty0 debug_non_panic_cpus=1 panic=10 ignore_loglevel log_buf_len=1M
[ 0.000000] BIOS-provided physical RAM map:
[ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved

But "dmesg" shows some numbers because it reads the messages
_after the calibration_:

[ 8.853613] Linux version 6.19.0-rc7-default+ (pmladek@pathway) (gcc (SUSE Linux) 15.2.1 20251006, GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.45.0.20251103-2) #521 SMP PREEMPT_DYNAMIC Mon Feb 2 16:36:53 CET 2026
[ 8.853617] Command line: BOOT_IMAGE=/boot/vmlinuz-6.19.0-rc7-default+ root=UUID=587ae802-e330-4059-9b48-d5b845e1075a resume=/dev/disk/by-uuid/369c7453-3d16-409d-88b2-5de027891a12 mitigations=auto nosplash earlycon=uart8250,io,0x3f8,115200 console=ttyS0,115200 console=ttynull console=tty0 debug_non_panic_cpus=1 panic=10 ignore_loglevel log_buf_len=1M
[ 8.865086] BIOS-provided physical RAM map:
[ 8.865087] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[ 8.865089] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved

2. Early messages added _after the timekeeping_ is initialized
but _before the early cycles calibration_.

They serial console prints them _without the offset_ because
it reads them _before the calibration_, e.g.

[ 3.288049][ T1] Write protecting the kernel read-only data: 36864k
[ 3.298554][ T1] Freeing unused kernel image (text/rodata gap) memory: 1656K
[ 3.318942][ T1] Freeing unused kernel image (rodata/data gap) memory: 1540K

But "dmesg" prints them _with the offset_ because it reads them
_after the calibration_, e.g.

[ 12.179999] [ T1] Write protecting the kernel read-only data: 36864k
[ 12.190505] [ T1] Freeing unused kernel image (text/rodata gap) memory: 1656K
[ 12.210893] [ T1] Freeing unused kernel image (rodata/data gap) memory: 1540K

3. Messages added after the calibration of the early cycles.

They are printed with the offset by both serial console and
dmesg, e.g.

[ 12.230014][ T1] Early printk times: mult=38775352, shift=27, offset=8891950261 ns
[ 12.246008][ T1] Run /init as init process
[ 12.254944][ T1] with arguments:
[ 12.264341][ T1] /init

> An accessor can be implemented for (struct printk_info).ts_nsec, say
> get_timestamp(), which can be called from both the places.

Yeah, a helper function for reading the timestamp might be a cleaner solution.

> [1] https://lore.kernel.org/all/aYDPn2EJgJIWGDhM@pathway/

Everything seems to be as expected there. The non-zero timestamps
on the serial console are from messages added after the timekeeping
was initialized.

Best Regards,
Petr