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

[Brian Masney <bmasney@redhat.com>]

Hi Thomas,

On Wed, Apr 01, 2026 at 01:36:26AM +0200, Thomas Gleixner wrote:
> On Tue, Mar 31 2026 at 11:10, Thomas Gleixner wrote:
> > So the real good question is whether the extra information of how long
> > that earliest init takes is really relevant to the goal of optimizing
> > boot time. The expensive part of the boot process definitely comes after
> > that.
> 
> That actually made me curious and so I hacked up the kernel with the
> patch below to compensate for the difference between:
> 
>   x86_64_start_reservations()
> 
> 	i.e. the C entry point of the kernel and the actual earliest
> 	point (ASM entry code aside) where the kernel can take a
> 	timestamp, which is modulo the sanity checks in the PoC the same
> 	thing, right?
> 
> and
> 
>   tsc_early_init()
> 
>         where the upstream kernel enables TSC sched clock today with all
>         sanity checks and enumeration in place.
> 
> Here is the result on a bare metal 256 CPU machine:
> 
> [    0.000000] Linux version 7.0.0-rc3-dirty ...
> 
> ....
> 
> [    0.000000] tsc: Detected 2100.000 MHz processor
> [    0.012482] e820: update [mem 0x00000000-0x00000fff] System RAM ==> device reserved
> 
> That's ~12ms of time which is not accounted for in the overall boot time
> until the machine reaches the init process:
> 
> [   12.289141] Run /init as init process
> 
> That means we are talking about ~0.1% of overall boot time in this case.
> 
> Starting a 4 CPU guest with the same kernel image on the same physical
> machine and additionally 'no-kvmclock' on the command line to make the
> hack work:
> 
> [    0.000000] Linux version 7.0.0-rc3-dirty ...
> 
> ...
> 
> [    0.000000] tsc: Detected 2094.965 MHz processor
> [    0.015122] last_pfn = 0x280000 max_arch_pfn = 0x400000000
> 
> Unsurpringly it takes a bit longer because during that phase the guest
> takes a gazillion of vmexits.
> 
> [    0.995082] Run /init as init process
> 
> Now in this 4 CPU case we are talking about 1.5% of the overall boot
> time.
> 
> With the same setup and 32 CPUs in the VM:
> 
> [    0.015150] e820: remove [mem 0x000a0000-0x000fffff] System RAM
> 
> The initial phase takes 30us more than with 4 CPUs, which is in the
> noise and the machine ends up in init at:
> 
> [    3.329398] Run /init as init process
> 
> which means in total we are up to 0.45% of the overall boot time now.
> 
> I'm honestly confused. May I politely ask which problem you are trying
> to solve?

A recent example of where this was a problem was in the creation of the
arm64 linear map:

https://lore.kernel.org/all/20240412131908.433043-1-ryan.roberts@arm.com/

The boot time was all reported as 0, however we could tell there was a
boot delay based on the timing of the firmware / other linux logs in the
serial console. Eric Chanudet @ Red Hat (CCed) used the cntvct arch
counters on arm64 to track down this unreported time to the linear map
creation.

With this patch set, on a 32GB RAM arm64 system we have the linear map
creation time went from ~350ms to 25ms. Again, the boot time was all
reported as 0 in dmesg.

What Tim is trying to do is to identify if we have points like this on
other systems, or if boot regressions are introduced in the future.

Brian