Message-ID: <CAPDLWs-oikjGMDE1L36UETaN75D6n87E+MLtqRmetHiyhHPA6Q@mail.gmail.com>
Date: Mon, 1 Sep 2025 11:27:15 +0530
From: Kaiwan N Billimoria <kaiwan.billimoria@...il.com>
To: tglx@...utronix.de
Cc: Llillian@...r-ark.net, agordeev@...ux.ibm.com, akpm@...ux-foundation.org, 
	alexander.shishkin@...ux.intel.com, anna-maria@...utronix.de, 
	bigeasy@...utronix.de, catalin.marinas@....com, chenhuacai@...nel.org, 
	francesco@...la.it, frederic@...nel.org, guoweikang.kernel@...il.com, 
	jstultz@...gle.com, kpsingh@...nel.org, linux-arm-kernel@...ts.infradead.org, 
	linux-kernel@...r.kernel.org, mark.rutland@....com, maz@...nel.org, 
	mingo@...nel.org, pmladek@...e.com, rrangel@...omium.org, sboyd@...nel.org, 
	urezki@...il.com, v-singh1@...com, will@...nel.org
Subject: Re:

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@...il.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@...il.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@...il.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@...gleBone:~$ 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.

Powered by blists - more mailing lists