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

Petr Mladek
2026-03-11T15:45:55Z

On Tue 2026-03-10 18:54:22, Bird, Tim wrote:
> > From: Petr Mladek <pmladek@suse.com>
> > 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
>
> This is correct. I don't want to overwhelm users of this, but there are three time-gathering periods, and roughly
> 2 output times (before calibration and after calibration).
>
> early boot = before time init, before cycles calibration and offset calculation
> mid boot = after time init, before cycles calibration and offset calculation
> late boot = after time init, after cycles calibration and offset calculation
> All of these are before the start of user space processes.
>
> time of printk output time timestamp type stored timestamp output
> ------------------ ---------------- ----------------------------- ------------------------
> early boot early boot cycles 0
> mid boot mid-boot nanosecs seconds, with offset from time_init
> late boot late-boot nanosecs seconds with offset from cycle counter start

This is a bit confusing. I looks like the offset from time_init() is
not longer added.

> -----
> early boot post-boot (cycles already stored) seconds with offset from cycle counter start
> mid boot post-boot (ns already stored) seconds with offset from cycle counter start
> late boot post-boot (ns already stored) seconds with offset from cycle counter start
> all others post-boot nanosecs seconds with offset from cycle counter start

> The confusing thing is messages that are output to the console before calibration and offset calculation.
> Reports from all user space tools (ie from dmesg or journalctl) should be correct and consistent.

Yup.

I like that table. I just wonder how to better distinguish the offset from
timekeeping and calibrated cycles. My variant:

<proposal>
The printk timestamps are stored and interpretted differently in
the following periods:

- early boot: before timekeeping init, before cycles calibration
- mid boot: after timekeeping init, before cycles calibration
- late boot: after timekeeping init, after cycles calibration

Console output (immediately):

printk() time stored value immediate output(sec)
-----------------------------------------------------------------------------
early boot cycles 0
mid boot get_time() get_time()
late boot get_time() get_time + calibrated(cycles offset)

User space tools and late registered consoles:

printk() time stored value output after calibration (sec)
-----------------------------------------------------------------------------
early boot cycles calibrated(cycles)
mid boot get_time() get_time() + calibrated(cycles offset)
late boot get_time() get_time() + calibrated(cycles offset)

I am not sure where to put this. One place might be
Documentation/core-api/printk-basics.rst. But it might be better
add a separate file either under core-api/ or under admin-guide/.

> >
> > > 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.
> >
> I consider adjust_early_ts() to be such an accessor function. It's supposed
> to hide the details of the type of the timestamp (cycles or ns) and
> the offset. Maybe this could be renamed to something better,
> like: get_adjusted_ts()? Let me know what you think.

This a bike shedding area ;-)

I personally find

u64 ts = get_printk_info_ts(info);

a bit cleaner than

u64 ts = adjust_early_ts(info->ts_nsec);

because you might add a comment into struct printk_info
definition that nobody should read the timestamp directly.
They should use the helper intead.

The helper would do something like:

/*
* The number of early cycles is stored before the timekeeping gets initialized.
* The local_clock() value is stored later.
*
* Note that early_ts_offset, early_mult, and early_shift are 0
* before the cycles get calibrated against the official time keeping.
*
* Any output after user space start (eg. from dmesg or journalctl)
* will show consistent values with calibrated cycles and offset.
*/
static inline u64 get_printk_info_ts(const struct printk_info *info)
{
if (likely(!(info->ts_cycles & EARLY_CYCLES_BIT)))
/* if timestamp is not in cycles, just add offset */
return info->ts_nsec + early_ts_offset;

/* mask high bit and convert to nanoseconds */
return mul_u64_u32_shr(info->ts_cycles & EARLY_CYCLES_MASK,
early_mult, early_shift);
}

Note that I have already used two names (ts_cycles and ts_nsec) which
would point to the same data via an union.

> I'll rebase this patch to resolve the #include conflicts, and address
> this feedback, and hopefully get a new version out this week.

Thanks a lot. v3 looked good enough to me. But v4 will be even better
after the feedback.

Take your time ;-)

Best Regards,
Petr