Re:

Kaiwan N Billimoria
2025-09-01T05:57:34Z

Apologies, subject missing; it's:
time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

On Mon, Sep 1, 2025 at 9:36 AM Kaiwan N Billimoria
<kaiwan.billimoria@gmail.com> wrote:
>
> > What the heck is BOOT SIG Initiative?
> Very, very briefly: it's an initiative that plans to measure the complete or
> unified boot time, i.e., the time it takes to boot the system completely. This
> includes (or plans to) track the time taken for:
> - Boot from CPU power-on, ROM code execution
> - 1st, 2nd, (and possibly) 3rd stage bootloader(s)
> - Linux kernel upto running the PID 1 process
> - Include time taken for onboard MCUs (and their apps to come up).
>
> The plan is to be able to show the cumulative and individual times taken across
> all of these. Then report it via ASCII text and a GUI system (as of now, a HTML
> file).
> For anyone interested, here's the PDF of a super presentation on this topic by
> Vishnu P Singh (OP) this August at the OSS EU:
> https://static.sched.com/hosted_files/osseu2025/a2/EOSS_2025_Unified%20Boot%20Time%20log%20based%20measurement.pdf
> As mentioned by Vishnu, the work is in the very early dev stages.
>
> > - pr_info("sched_clock: %u bits at %lu%cHz, resolution %lluns, wraps every %lluns\n",
> > - bits, r, r_unit, res, wrap);
> > + pr_info("sched_clock: %pS: %u bits at %lu%cHz, resolution %lluns, wraps every %lluns hwcnt: %llu\n",
> > + read, bits, r, r_unit, res, wrap, read());
> --snip--
> > So let's assume this give you
> >
> > [ 0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps
> > every 3579139424256ns hwcnt: 19000000
> >
> > Which means that the counter accumulated 19000000 increments since the
> > hardware was powered up, no?
> I agree with your approach Thomas (tglx)! (eye-roll)... So, following this
> approach, here's the resulting tiny patch:
>
> From 1e687ab12269f5f129b17eb7e9c3c5c2cec441b7 Mon Sep 17 00:00:00 2001
> From: Kaiwan N Billimoria <kaiwan.billimoria@gmail.com>
> Date: Mon, 1 Sep 2025 09:17:57 +0530
> Subject: [PATCH] [sched-clock] Extend printk to show h/w counter in a
> parseable manner
>
> Signed-off-by: Kaiwan N Billimoria <kaiwan.billimoria@gmail.com>
> ---
> kernel/time/sched_clock.c | 6 ++----
> 1 file changed, 2 insertions(+), 4 deletions(-)
>
> diff --git a/kernel/time/sched_clock.c b/kernel/time/sched_clock.c
> index cc15fe293719..e4fe900d6b60 100644
> --- a/kernel/time/sched_clock.c
> +++ b/kernel/time/sched_clock.c
> @@ -236,16 +236,14 @@ sched_clock_register(u64 (*read)(void), int bits, unsigned long rate)
> /* Calculate the ns resolution of this counter */
> res = cyc_to_ns(1ULL, new_mult, new_shift);
>
> - pr_info("sched_clock: %u bits at %lu%cHz, resolution %lluns, wraps every %lluns\n",
> - bits, r, r_unit, res, wrap);
> + pr_info("sched_clock: %pS: bits=%u,freq=%lu %cHz,resolution=%llu ns,wraps every=%llu ns,hwcnt=%llu\n",
> + read, bits, r, r_unit, res, wrap, read());
>
> /* Enable IRQ time accounting if we have a fast enough sched_clock() */
> if (irqtime > 0 || (irqtime == -1 && rate >= 1000000))
> enable_sched_clock_irqtime();
>
> local_irq_restore(flags);
> -
> - pr_debug("Registered %pS as sched_clock source\n", read);
> }
>
> void __init generic_sched_clock_init(void)
> --
> 2.43.0
>
> Of course, this is almost identical to what Thomas has already shown. I've
> added some formatting to make for easier parsing. A sample output obtained with
> this code on a patched kernel for the BeaglePlay k3 am625 board:
> [ 0.000001] sched_clock: arch_counter_get_cntpct+0x0/0x18: bits=58,freq=200 MHz,resolution=5 ns,wraps every=4398046511102 ns,hwcnt=1409443611
>
> This printk format allows us to easily parse it; f.e. to obtain the hwcnt value:
> debian@BeagleBone:~$ dmesg |grep sched_clock |awk -F, '{print $5}'
> hwcnt=1409443611
>
> So, just confirming: here 1409443611 divided by 200 MHz gives us 7.047218055s
> since boot, and thus the actual timestamp here is that plus 0.000001s yes?
> (Over 7s here? yes, it's just that I haven't yet setup U-Boot properly for uSD
> card boot, thus am manually loading commands in U-Boot to boot up, that's all).
>
> A question (perhaps very stupid): will the hwcnt - the output of the read() -
> be guaranteed to be (close to) the number of increments since processor
> power-up (or reset)? Meaning, it's simply a hardware feature and agnostic to
> what code the core was executing (ROM/BL/kernel), yes?
> If so, I guess we can move forward with this approach... Else, or otherwise,
> suggestions are welcome,
>
> Regards,
> Kaiwan.