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

On Tue 2026-03-10 18:54:22, Bird, Tim wrote:
> > From: Petr Mladek <[email protected]>
> > 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