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

Petr Mladek
2026-02-02T16:24:03Z

On Mon 2026-01-26 16:52:57, Bird, Tim wrote:
>
>
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> >
> > 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