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

On Mon 2026-01-26 16:52:57, Bird, Tim wrote:
> 
> 
> > -----Original Message-----
> > From: Francesco Valla <[email protected]>
> > 
> > Hi Tim,
> > 
> > I tested this both on X86_64 QEMU and on a i.MX93 (ARM64) and can
> > confirm it is working as expected. Auto-calc of calibration data is far
> > better than the configuration parameters in v1.
> > 
> > It is slightly confusing to see a time value printed to serial output
> > and another one inside kmsg, but that's a human thing and should not
> > confuse any tool.
> Agreed.  I wasn't too worried about it, because most serious developers working
> on boot-time will not be watching early messages over serial console.  (Usually they
> use 'quiet' or some lower log level).  But on qemu, it does look strange to see 0s
> on the first output sequence, and then non-zeroes when using dmesg later in the same
> boot.
> 
> I just realized though, that I should go back and see if there's a discontinuity on the output via serial
> (before and after calibration), and possibly put a note about that in the config description.

I see the following in the serial console output:

[    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
[   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
[   12.272184][    T1]     nosplash

And this is from dmesg -S

[   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
[   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
[   12.272184] [    T1]     nosplash

> I'll think about what I can do here to reduce the confusion.

I though about showing the non-adjusted timestamp with '?',
Something like:

[    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
[   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
[   12.272184][    T1]     nosplash

But I am afraid that it might break some monitoring tools.

Well, it might be acceptable when this feature is not enabled
in production systems.

> > > --- a/init/Kconfig
> > > +++ b/init/Kconfig
> > > @@ -777,6 +777,18 @@ 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 y
> > 
> > Considering that this might have a significant impact on monitoring
> > mechanisms already in place (that e.g. expect a specific dmesg print to
> > have a maximum associated time value), please consider a N default here.
> 
> Oops!  Sorry, that was supposed to be 'default n'.  You're right.  I know I had
> this as default N, and I think I switched it temporarily for testing, and forgot
> to switch it back (and never caught it the numerous times I reviewed the
> patch before sending it out again, ugh).  Thanks for catching this.
> 
> If people like this, and we don't see any problems with tooling or virtualization, I
> could see it switching to default Y in the future.  But for now this should definitely
> be 'default n'.

We need to be careful. The different output on console and via dmesg
might confuse people. The extra '?' might help poeple but it might confuse
tools.

> > 
> > > +	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 machine power on, instead
> > > +	  of relative to the start of kernel timekeeping.
> > > +
> > 
> > To be precise, the timestamps will be relative to processor power on;
> > the machine might have some other processors that run before the Linux
> > one (this is the case for example of i.MX9 or AM62 SoCs) and will be
> > unaccounted for even by this mechanism.
> 
> Good point.   Even more precisely, it will be relative to
> cycle-counter value initialization or reset, which often (but not always)
> corresponds to processor power on.
> 
> I'll adjust the wording.
> 
> I'm still a bit unsure what happens in the virtualization case.  qemu seems to initialize
> the TSC at qemu start, but I'm not sure what happens for e.g. client VMs on cloud servers.

I see the following via QEMU (from dmesg):

[    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
[    8.865090] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    8.865090] BIOS-e820: [mem 0x0000000000100000-0x000000007ffdbfff] usable
[    8.865091] BIOS-e820: [mem 0x000000007ffdc000-0x000000007fffffff] reserved
[    8.865092] BIOS-e820: [mem 0x00000000b0000000-0x00000000bfffffff] reserved
[    8.865092] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    8.865093] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    8.865093] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    8.865094] BIOS-e820: [mem 0x0000000100000000-0x000000017fffffff] usable
[    8.865094] BIOS-e820: [mem 0x000000fd00000000-0x000000ffffffffff] reserved
[    8.865171] earlycon: uart8250 at I/O port 0x3f8 (options '115200')
[    8.865176] printk: legacy bootconsole [uart8250] enabled
[    8.892181] printk: allow messages from non-panic CPUs in panic()
[    8.893327] printk: debug: ignoring loglevel setting.
[...]
[   12.162011] Freeing unused decrypted memory: 2036K
[   12.171970] Freeing unused kernel image (initmem) memory: 7120K
[   12.179999] Write protecting the kernel read-only data: 36864k
[   12.190505] Freeing unused kernel image (text/rodata gap) memory: 1656K
[   12.210893] Freeing unused kernel image (rodata/data gap) memory: 1540K
[   12.230014] Early printk times: mult=38775352, shift=27, offset=8891950261 ns
[   12.246008] Run /init as init process
[   12.254944]   with arguments:
[   12.264341]     /init
[   12.272184]     nosplash
[   12.280738]   with environment:
[   12.288728]     HOME=/
[   12.296319]     TERM=linux

Best Regards,
Petr