[RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[vishnu singh]

From: Vishnu Singh <v-singh1@ti.com>

Part of BOOT SIG Initiative, This patch adds a tiny,opt-in facility to
help measure kernel boot duration without full tracing:

New CONFIG_BOOT_TIME_TRACKER in kernel/time/Kconfig.
When enabled, the kernel logs two boot markers:
    1. kernel entry in start_kernel()
    2. first userspace start in kernel_init() before run_init_process()

These markers are intended for post-boot parsers to compute coarse
kernel boot time and to merge with bootloader/MCU/DSP records into
a unified timeline.

Core helper u64 boot_time_now() in kernel/time/boot_time_now.c,
exporting a counter‑derived timestamp via small per-arch primitives.
This series includes an initial arm64 primitive that uses CNTVCT_EL0
as the source, other architectures can wire up equivalents.

Files touched:
kernel/time/Kconfig, kernel/time/Makefile
kernel/time/boot_time_now.c (new core helper)
arch/arm64/include/asm/boot_time_primitives.h (arm64 primitive)
include/linux/boot_time_now.h (public API + IDs)
init/main.c (print two markers)

This complements U-Boot’s stashed bootstage records so a userspace tool
can build a system-wide boot timeline across SPL, U-Boot, kernel and other
subsystems.

Reference boot-time parser utility:
     https://github.com/v-singh1/boot-time-parser

Sample boot time report:
+--------------------------------------------------------------------+
                 am62xx-evm Boot Time Report
+--------------------------------------------------------------------+
Device Power On         : 0 ms
SPL Time                : 843 ms
U-Boot Time             : 2173 ms
Kernel handoff time     : 462 ms
Kernel Time             : 2522 ms
Total Boot Time         : 6000 ms
+--------------------------------------------------------------------+

+--------------------------------------------------------------------+
                 Bootloader and Kernel Boot Records
+--------------------------------------------------------------------+
BOOTSTAGE_AWAKE                =      0 ms (+  0 ms)
BOOTSTAGE_START_UBOOT_F        =    843 ms (+  0 ms)
BOOTSTAGE_ACCUM_DM_F           =    843 ms (+  0 ms)
BOOTSTAGE_START_UBOOT_R        =   1951 ms (+1108 ms)
BOOTSTAGE_ACCUM_DM_R           =   1951 ms (+  0 ms)
BOOTSTAGE_NET_ETH_START        =   2032 ms (+ 81 ms)
BOOTSTAGE_NET_ETH_INIT         =   2053 ms (+ 21 ms)
BOOTSTAGE_MAIN_LOOP            =   2055 ms (+  2 ms)
BOOTSTAGE_START_MCU            =   2661 ms (+606 ms)
BOOTSTAGE_BOOTM_START          =   2959 ms (+298 ms)
BOOTSTAGE_RUN_OS               =   3016 ms (+ 57 ms)
BOOTSTAGE_BOOTM_HANDOFF        =   3016 ms (+  0 ms)
BOOTSTAGE_KERNEL_START         =   3478 ms (+462 ms)
BOOTSTAGE_KERNEL_END           =   6000 ms (+2522 ms)
+--------------------------------------------------------------------+

+--------------------------------------------------------------------+
                 MCU Boot Records
+--------------------------------------------------------------------+
MCU_AWAKE                      =   2661 ms (+  0 ms)
BOARD_PERIPHERALS_INIT         =   2661 ms (+  0 ms)
MAIN_TASK_CREATE               =   2661 ms (+  0 ms)
FIRST_TASK                     =   2662 ms (+  1 ms)
DRIVERS_OPEN                   =   2662 ms (+  0 ms)
BOARD_DRIVERS_OPEN             =   2662 ms (+  0 ms)
IPC_SYNC_FOR_LINUX             =   6636 ms (+3974 ms)
IPC_REGISTER_CLIENT            =   6636 ms (+  0 ms)
IPC_SUSPEND_TASK               =   6636 ms (+  0 ms)
IPC_RECEIVE_TASK               =   6636 ms (+  0 ms)
IPC_SYNC_ALL                   =   6787 ms (+151 ms)
+--------------------------------------------------------------------+

Signed-off-by: Vishnu Singh <v-singh1@ti.com>
---
 MAINTAINERS                                   |  3 +++
 arch/arm64/include/asm/boot_time_primitives.h | 14 ++++++++++++++
 include/linux/boot_time_now.h                 | 16 ++++++++++++++++
 init/main.c                                   | 13 +++++++++++++
 kernel/time/Kconfig                           | 10 ++++++++++
 kernel/time/Makefile                          |  1 +
 kernel/time/boot_time_now.c                   | 13 +++++++++++++
 7 files changed, 70 insertions(+)
 create mode 100644 arch/arm64/include/asm/boot_time_primitives.h
 create mode 100644 include/linux/boot_time_now.h
 create mode 100644 kernel/time/boot_time_now.c

diff --git a/MAINTAINERS b/MAINTAINERS
index e913c1edd1fd..e5273b338814 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -1994,6 +1994,7 @@ L:	linux-arm-kernel@lists.infradead.org (moderated for non-subscribers)
 S:	Maintained
 F:	arch/arm/include/asm/arch_timer.h
 F:	arch/arm64/include/asm/arch_timer.h
+F:	arch/arm64/include/asm/boot_time_primitives.h
 F:	drivers/clocksource/arm_arch_timer.c
 F:	drivers/clocksource/arm_arch_timer_mmio.c
 
@@ -25466,6 +25467,7 @@ R:	Stephen Boyd <sboyd@kernel.org>
 L:	linux-kernel@vger.kernel.org
 S:	Supported
 T:	git git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git timers/core
+F:	include/linux/boot_time_now.h
 F:	include/linux/clocksource.h
 F:	include/linux/time.h
 F:	include/linux/timekeeper_internal.h
@@ -25474,6 +25476,7 @@ F:	include/linux/timex.h
 F:	include/uapi/linux/time.h
 F:	include/uapi/linux/timex.h
 F:	kernel/time/alarmtimer.c
+F:	kernel/time/boot_time_now.c
 F:	kernel/time/clocksource*
 F:	kernel/time/ntp*
 F:	kernel/time/time.c
diff --git a/arch/arm64/include/asm/boot_time_primitives.h b/arch/arm64/include/asm/boot_time_primitives.h
new file mode 100644
index 000000000000..9bbbd500a95d
--- /dev/null
+++ b/arch/arm64/include/asm/boot_time_primitives.h
@@ -0,0 +1,14 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef __ASM_BOOT_TIME_PRIMITIVES_H
+#define __ASM_BOOT_TIME_PRIMITIVES_H
+
+#include <asm/arch_timer.h>
+#include <linux/math64.h>
+
+static inline u64 arch_boot_counter_now(void)
+{
+	return ((arch_timer_read_cntvct_el0() * 1000000) / arch_timer_get_cntfrq());
+}
+
+#endif
diff --git a/include/linux/boot_time_now.h b/include/linux/boot_time_now.h
new file mode 100644
index 000000000000..a18a1809057f
--- /dev/null
+++ b/include/linux/boot_time_now.h
@@ -0,0 +1,16 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _LINUX_BOOT_TRACKER_H
+#define _LINUX_BOOT_TRACKER_H
+
+#include <linux/types.h>
+
+enum kernel_bootstage_id {
+	BOOTSTAGE_ID_KERNEL_START = 300,
+	BOOTSTAGE_ID_KERNEL_END = 301,
+};
+
+/* Return boot time in nanoseconds using hardware counter */
+u64 boot_time_now(void);
+
+#endif
diff --git a/init/main.c b/init/main.c
index 9b5150166bcf..76eb8098ab20 100644
--- a/init/main.c
+++ b/init/main.c
@@ -115,6 +115,10 @@
 
 #include <kunit/test.h>
 
+#ifdef CONFIG_BOOT_TIME_TRACKER
+#include <linux/boot_time_now.h>
+#endif
+
 static int kernel_init(void *);
 
 /*
@@ -929,6 +933,11 @@ void start_kernel(void)
 	page_address_init();
 	pr_notice("%s", linux_banner);
 	setup_arch(&command_line);
+
+#ifdef CONFIG_BOOT_TIME_TRACKER
+	pr_info("[BOOT TRACKER] - ID:%d, %s = %llu\n",
+		BOOTSTAGE_ID_KERNEL_START, __func__, boot_time_now());
+#endif
 	/* Static keys and static calls are needed by LSMs */
 	jump_label_init();
 	static_call_init();
@@ -1503,6 +1512,10 @@ static int __ref kernel_init(void *unused)
 
 	do_sysctl_args();
 
+#ifdef CONFIG_BOOT_TIME_TRACKER
+	pr_info("[BOOT TRACKER] - ID:%d, %s = %llu\n",
+		BOOTSTAGE_ID_KERNEL_END, __func__, boot_time_now());
+#endif
 	if (ramdisk_execute_command) {
 		ret = run_init_process(ramdisk_execute_command);
 		if (!ret)
diff --git a/kernel/time/Kconfig b/kernel/time/Kconfig
index 7c6a52f7836c..aadfd66d5d69 100644
--- a/kernel/time/Kconfig
+++ b/kernel/time/Kconfig
@@ -221,4 +221,14 @@ config POSIX_AUX_CLOCKS
 	  and other clock domains, which are not correlated to the TAI/NTP
 	  notion of time.
 
+config BOOT_TIME_TRACKER
+	bool "boot time tracking support"
+	help
+	  Prints boot timestamps at the beginning of the kernel and when the
+	  first user-space process is launched. This helps measure basic
+	  boot latency for embedded and multi-core systems.
+
+	  The messages appear using printk and can be parsed by boot
+	  instrumentation tools or console logs.
+
 endmenu
diff --git a/kernel/time/Makefile b/kernel/time/Makefile
index e6e9b85d4db5..f7c115a385bb 100644
--- a/kernel/time/Makefile
+++ b/kernel/time/Makefile
@@ -32,3 +32,4 @@ obj-$(CONFIG_TEST_UDELAY)			+= test_udelay.o
 obj-$(CONFIG_TIME_NS)				+= namespace.o
 obj-$(CONFIG_TEST_CLOCKSOURCE_WATCHDOG)		+= clocksource-wdtest.o
 obj-$(CONFIG_TIME_KUNIT_TEST)			+= time_test.o
+obj-$(CONFIG_BOOT_TIME_TRACKER) 		+= boot_time_now.o
diff --git a/kernel/time/boot_time_now.c b/kernel/time/boot_time_now.c
new file mode 100644
index 000000000000..6dc12d454be0
--- /dev/null
+++ b/kernel/time/boot_time_now.c
@@ -0,0 +1,13 @@
+// SPDX-License-Identifier: LGPL-2.0
+
+#include <linux/boot_time_now.h>
+#include <asm/boot_time_primitives.h>
+
+u64 boot_time_now(void)
+{
+	return arch_boot_counter_now();
+}
+EXPORT_SYMBOL_GPL(boot_time_now);
+
+MODULE_DESCRIPTION("boot time tracker");
+MODULE_LICENSE("GPL");
-- 
2.50.1

[RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[vishnu singh]

From: Vishnu Singh <v-singh1@ti.com>

Part of BOOT SIG Initiative, This patch adds a tiny,opt-in facility to
help measure kernel boot duration without full tracing:

New CONFIG_BOOT_TIME_TRACKER in kernel/time/Kconfig.
When enabled, the kernel logs two boot markers:
    1. kernel entry in start_kernel()
    2. first userspace start in kernel_init() before run_init_process()

These markers are intended for post-boot parsers to compute coarse
kernel boot time and to merge with bootloader/MCU/DSP records into
a unified timeline.

Core helper u64 boot_time_now() in kernel/time/boot_time_now.c,
exporting a counter‑derived timestamp via small per-arch primitives.
This series includes an initial arm64 primitive that uses CNTVCT_EL0
as the source, other architectures can wire up equivalents.

Files touched:
kernel/time/Kconfig, kernel/time/Makefile
kernel/time/boot_time_now.c (new core helper)
arch/arm64/include/asm/boot_time_primitives.h (arm64 primitive)
include/linux/boot_time_now.h (public API + IDs)
init/main.c (print two markers)

This complements U-Boot’s stashed bootstage records so a userspace tool
can build a system-wide boot timeline across SPL, U-Boot, kernel and other
subsystems.

Reference boot-time parser utility:
     https://github.com/v-singh1/boot-time-parser

Sample boot time report:
+--------------------------------------------------------------------+
                 am62xx-evm Boot Time Report
+--------------------------------------------------------------------+
Device Power On         : 0 ms
SPL Time                : 843 ms
U-Boot Time             : 2173 ms
Kernel handoff time     : 462 ms
Kernel Time             : 2522 ms
Total Boot Time         : 6000 ms
+--------------------------------------------------------------------+

+--------------------------------------------------------------------+
                 Bootloader and Kernel Boot Records
+--------------------------------------------------------------------+
BOOTSTAGE_AWAKE                =      0 ms (+  0 ms)
BOOTSTAGE_START_UBOOT_F        =    843 ms (+  0 ms)
BOOTSTAGE_ACCUM_DM_F           =    843 ms (+  0 ms)
BOOTSTAGE_START_UBOOT_R        =   1951 ms (+1108 ms)
BOOTSTAGE_ACCUM_DM_R           =   1951 ms (+  0 ms)
BOOTSTAGE_NET_ETH_START        =   2032 ms (+ 81 ms)
BOOTSTAGE_NET_ETH_INIT         =   2053 ms (+ 21 ms)
BOOTSTAGE_MAIN_LOOP            =   2055 ms (+  2 ms)
BOOTSTAGE_START_MCU            =   2661 ms (+606 ms)
BOOTSTAGE_BOOTM_START          =   2959 ms (+298 ms)
BOOTSTAGE_RUN_OS               =   3016 ms (+ 57 ms)
BOOTSTAGE_BOOTM_HANDOFF        =   3016 ms (+  0 ms)
BOOTSTAGE_KERNEL_START         =   3478 ms (+462 ms)
BOOTSTAGE_KERNEL_END           =   6000 ms (+2522 ms)
+--------------------------------------------------------------------+

+--------------------------------------------------------------------+
                 MCU Boot Records
+--------------------------------------------------------------------+
MCU_AWAKE                      =   2661 ms (+  0 ms)
BOARD_PERIPHERALS_INIT         =   2661 ms (+  0 ms)
MAIN_TASK_CREATE               =   2661 ms (+  0 ms)
FIRST_TASK                     =   2662 ms (+  1 ms)
DRIVERS_OPEN                   =   2662 ms (+  0 ms)
BOARD_DRIVERS_OPEN             =   2662 ms (+  0 ms)
IPC_SYNC_FOR_LINUX             =   6636 ms (+3974 ms)
IPC_REGISTER_CLIENT            =   6636 ms (+  0 ms)
IPC_SUSPEND_TASK               =   6636 ms (+  0 ms)
IPC_RECEIVE_TASK               =   6636 ms (+  0 ms)
IPC_SYNC_ALL                   =   6787 ms (+151 ms)
+--------------------------------------------------------------------+

Signed-off-by: Vishnu Singh <v-singh1@ti.com>
---
 MAINTAINERS                                   |  3 +++
 arch/arm64/include/asm/boot_time_primitives.h | 14 ++++++++++++++
 include/linux/boot_time_now.h                 | 16 ++++++++++++++++
 init/main.c                                   | 13 +++++++++++++
 kernel/time/Kconfig                           | 10 ++++++++++
 kernel/time/Makefile                          |  1 +
 kernel/time/boot_time_now.c                   | 13 +++++++++++++
 7 files changed, 70 insertions(+)
 create mode 100644 arch/arm64/include/asm/boot_time_primitives.h
 create mode 100644 include/linux/boot_time_now.h
 create mode 100644 kernel/time/boot_time_now.c

diff --git a/MAINTAINERS b/MAINTAINERS
index e913c1edd1fd..e5273b338814 100644
--- a/MAINTAINERS
+++ b/MAINTAINERS
@@ -1994,6 +1994,7 @@ L:	linux-arm-kernel@lists.infradead.org (moderated for non-subscribers)
 S:	Maintained
 F:	arch/arm/include/asm/arch_timer.h
 F:	arch/arm64/include/asm/arch_timer.h
+F:	arch/arm64/include/asm/boot_time_primitives.h
 F:	drivers/clocksource/arm_arch_timer.c
 F:	drivers/clocksource/arm_arch_timer_mmio.c
 
@@ -25466,6 +25467,7 @@ R:	Stephen Boyd <sboyd@kernel.org>
 L:	linux-kernel@vger.kernel.org
 S:	Supported
 T:	git git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip.git timers/core
+F:	include/linux/boot_time_now.h
 F:	include/linux/clocksource.h
 F:	include/linux/time.h
 F:	include/linux/timekeeper_internal.h
@@ -25474,6 +25476,7 @@ F:	include/linux/timex.h
 F:	include/uapi/linux/time.h
 F:	include/uapi/linux/timex.h
 F:	kernel/time/alarmtimer.c
+F:	kernel/time/boot_time_now.c
 F:	kernel/time/clocksource*
 F:	kernel/time/ntp*
 F:	kernel/time/time.c
diff --git a/arch/arm64/include/asm/boot_time_primitives.h b/arch/arm64/include/asm/boot_time_primitives.h
new file mode 100644
index 000000000000..9bbbd500a95d
--- /dev/null
+++ b/arch/arm64/include/asm/boot_time_primitives.h
@@ -0,0 +1,14 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef __ASM_BOOT_TIME_PRIMITIVES_H
+#define __ASM_BOOT_TIME_PRIMITIVES_H
+
+#include <asm/arch_timer.h>
+#include <linux/math64.h>
+
+static inline u64 arch_boot_counter_now(void)
+{
+	return ((arch_timer_read_cntvct_el0() * 1000000) / arch_timer_get_cntfrq());
+}
+
+#endif
diff --git a/include/linux/boot_time_now.h b/include/linux/boot_time_now.h
new file mode 100644
index 000000000000..a18a1809057f
--- /dev/null
+++ b/include/linux/boot_time_now.h
@@ -0,0 +1,16 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+
+#ifndef _LINUX_BOOT_TRACKER_H
+#define _LINUX_BOOT_TRACKER_H
+
+#include <linux/types.h>
+
+enum kernel_bootstage_id {
+	BOOTSTAGE_ID_KERNEL_START = 300,
+	BOOTSTAGE_ID_KERNEL_END = 301,
+};
+
+/* Return boot time in nanoseconds using hardware counter */
+u64 boot_time_now(void);
+
+#endif
diff --git a/init/main.c b/init/main.c
index 9b5150166bcf..76eb8098ab20 100644
--- a/init/main.c
+++ b/init/main.c
@@ -115,6 +115,10 @@
 
 #include <kunit/test.h>
 
+#ifdef CONFIG_BOOT_TIME_TRACKER
+#include <linux/boot_time_now.h>
+#endif
+
 static int kernel_init(void *);
 
 /*
@@ -929,6 +933,11 @@ void start_kernel(void)
 	page_address_init();
 	pr_notice("%s", linux_banner);
 	setup_arch(&command_line);
+
+#ifdef CONFIG_BOOT_TIME_TRACKER
+	pr_info("[BOOT TRACKER] - ID:%d, %s = %llu\n",
+		BOOTSTAGE_ID_KERNEL_START, __func__, boot_time_now());
+#endif
 	/* Static keys and static calls are needed by LSMs */
 	jump_label_init();
 	static_call_init();
@@ -1503,6 +1512,10 @@ static int __ref kernel_init(void *unused)
 
 	do_sysctl_args();
 
+#ifdef CONFIG_BOOT_TIME_TRACKER
+	pr_info("[BOOT TRACKER] - ID:%d, %s = %llu\n",
+		BOOTSTAGE_ID_KERNEL_END, __func__, boot_time_now());
+#endif
 	if (ramdisk_execute_command) {
 		ret = run_init_process(ramdisk_execute_command);
 		if (!ret)
diff --git a/kernel/time/Kconfig b/kernel/time/Kconfig
index 7c6a52f7836c..aadfd66d5d69 100644
--- a/kernel/time/Kconfig
+++ b/kernel/time/Kconfig
@@ -221,4 +221,14 @@ config POSIX_AUX_CLOCKS
 	  and other clock domains, which are not correlated to the TAI/NTP
 	  notion of time.
 
+config BOOT_TIME_TRACKER
+	bool "boot time tracking support"
+	help
+	  Prints boot timestamps at the beginning of the kernel and when the
+	  first user-space process is launched. This helps measure basic
+	  boot latency for embedded and multi-core systems.
+
+	  The messages appear using printk and can be parsed by boot
+	  instrumentation tools or console logs.
+
 endmenu
diff --git a/kernel/time/Makefile b/kernel/time/Makefile
index e6e9b85d4db5..f7c115a385bb 100644
--- a/kernel/time/Makefile
+++ b/kernel/time/Makefile
@@ -32,3 +32,4 @@ obj-$(CONFIG_TEST_UDELAY)			+= test_udelay.o
 obj-$(CONFIG_TIME_NS)				+= namespace.o
 obj-$(CONFIG_TEST_CLOCKSOURCE_WATCHDOG)		+= clocksource-wdtest.o
 obj-$(CONFIG_TIME_KUNIT_TEST)			+= time_test.o
+obj-$(CONFIG_BOOT_TIME_TRACKER) 		+= boot_time_now.o
diff --git a/kernel/time/boot_time_now.c b/kernel/time/boot_time_now.c
new file mode 100644
index 000000000000..6dc12d454be0
--- /dev/null
+++ b/kernel/time/boot_time_now.c
@@ -0,0 +1,13 @@
+// SPDX-License-Identifier: LGPL-2.0
+
+#include <linux/boot_time_now.h>
+#include <asm/boot_time_primitives.h>
+
+u64 boot_time_now(void)
+{
+	return arch_boot_counter_now();
+}
+EXPORT_SYMBOL_GPL(boot_time_now);
+
+MODULE_DESCRIPTION("boot time tracker");
+MODULE_LICENSE("GPL");
-- 
2.50.1

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Thomas Gleixner]

On Sat, Aug 23 2025 at  9:49, vishnu singh wrote:
On Sat, Aug 23 2025 at 10:10, vishnu singh wrote:

Why are you sending the same thing twice within 20 minutes?

> From: Vishnu Singh <v-singh1@ti.com>
>
> Part of BOOT SIG Initiative,

What the heck is BOOT SIG Initiative? Are you seriously expecting me to
look this up?

Please don't provide me a random link to it because it's not relevant to
the rest of what I have to say about this.

> , This patch adds a tiny,opt-in facility to help measure kernel boot
>   duration without full tracing:

1) Any spell checker would have pointed out to you that 'This' after a
   comma is not a proper sentence and neither is 'tiny,opt-in facility'

2) You failed to read documentation:

   # git grep "This patch" Documentation/process/

3) This change log starts with the WHAT and fails completely to explain
   the WHY. See:

     https://www.kernel.org/doc/html/latest/process/maintainer-tip.html#changelog

> New CONFIG_BOOT_TIME_TRACKER in kernel/time/Kconfig.
> When enabled, the kernel logs two boot markers:
>     1. kernel entry in start_kernel()
>     2. first userspace start in kernel_init() before run_init_process()
>
> These markers are intended for post-boot parsers to compute coarse
> kernel boot time and to merge with bootloader/MCU/DSP records into
> a unified timeline.
>
> Core helper u64 boot_time_now() in kernel/time/boot_time_now.c,
> exporting a counter‑derived timestamp via small per-arch primitives.
> This series includes an initial arm64 primitive that uses CNTVCT_EL0
> as the source, other architectures can wire up equivalents.
>
> Files touched:
> kernel/time/Kconfig, kernel/time/Makefile
> kernel/time/boot_time_now.c (new core helper)
> arch/arm64/include/asm/boot_time_primitives.h (arm64 primitive)
> include/linux/boot_time_now.h (public API + IDs)
> init/main.c (print two markers)

Seriously? This can be seen from the diffstat and the patch itself.

You still fail to explain the problem you are trying to solve and
instead babble about WHAT you are doing, which means you never read the
documentation of the project which you are trying to contribute to.

Do you really think that the people who spent time on writing it, did
so just to be ignored?

> This complements U-Boot’s stashed bootstage records so a userspace tool
> can build a system-wide boot timeline across SPL, U-Boot, kernel and other
> subsystems.
>
> Reference boot-time parser utility:
>      https://github.com/v-singh1/boot-time-parser
>
> Sample boot time report:
> +--------------------------------------------------------------------+
>                  am62xx-evm Boot Time Report
> +--------------------------------------------------------------------+
> Device Power On         : 0 ms

<SNIP>

> IPC_SYNC_ALL                   =   6787 ms (+151 ms)
> +--------------------------------------------------------------------+

How are these 30 lines of useless information helpful to understand the
underlying problem?

That's what cover letters are for.

>  MAINTAINERS                                   |  3 +++
>  arch/arm64/include/asm/boot_time_primitives.h | 14 ++++++++++++++
>  include/linux/boot_time_now.h                 | 16 ++++++++++++++++
>  init/main.c                                   | 13 +++++++++++++
>  kernel/time/Kconfig                           | 10 ++++++++++
>  kernel/time/Makefile                          |  1 +
>  kernel/time/boot_time_now.c                   | 13 +++++++++++++

This does too many things at once. See Documentation.

One patch for creating the infrastructure with a proper rationale and
then one which hooks it up.

Again:

    Documentation has not been written to be ignored. RFC patches are
    not exempt from that.

> +static inline u64 arch_boot_counter_now(void)
> +{
> +	return ((arch_timer_read_cntvct_el0() * 1000000) / arch_timer_get_cntfrq());
> +}

Q: What guarantees that this timer is available and functional at this
   point?

A: Nothing

> +++ b/include/linux/boot_time_now.h

What means boot_time_now?

You couldn't come up with a less non-descriptive name, right?

> +enum kernel_bootstage_id {
> +	BOOTSTAGE_ID_KERNEL_START = 300,
> +	BOOTSTAGE_ID_KERNEL_END = 301,

Aside of the formatting (See Documentation), these are random numbers
pulled out of thin air without any explanation why they need to start at
300.

> +};
> +
> +/* Return boot time in nanoseconds using hardware counter */
> +u64 boot_time_now(void);

That's a function name which is as bad as is can be. This is about
getting an early time stamp and that needs to be properly named _AND_
encapsulated so it works universally without some magic hardware
dependency. If at all, see below.

>  #include <kunit/test.h>
>  
> +#ifdef CONFIG_BOOT_TIME_TRACKER
> +#include <linux/boot_time_now.h>
> +#endif

What's this ifdeffery for? Headers have to be written in a way that they
can be unconditionally included. IOW, put the ifdeffery into the header.

> @@ -929,6 +933,11 @@ void start_kernel(void)
>  	page_address_init();
>  	pr_notice("%s", linux_banner);
>  	setup_arch(&command_line);
> +
> +#ifdef CONFIG_BOOT_TIME_TRACKER
> +	pr_info("[BOOT TRACKER] - ID:%d, %s = %llu\n",
> +		BOOTSTAGE_ID_KERNEL_START, __func__, boot_time_now());
> +#endif

Seriously? Have you looked at all the functions invoked in this file?

Those which depend on a config have:

#ifdef CONFIG_FOO
void foo_init(void);
#else
static inline void foo_init(void) { }
#endif

in the headers to avoid this horrible #ifdef maze. No?

> diff --git a/kernel/time/boot_time_now.c b/kernel/time/boot_time_now.c
> new file mode 100644
> index 000000000000..6dc12d454be0
> --- /dev/null
> +++ b/kernel/time/boot_time_now.c
> @@ -0,0 +1,13 @@
> +// SPDX-License-Identifier: LGPL-2.0
> +
> +#include <linux/boot_time_now.h>
> +#include <asm/boot_time_primitives.h>
> +
> +u64 boot_time_now(void)
> +{
> +	return arch_boot_counter_now();
> +}
> +EXPORT_SYMBOL_GPL(boot_time_now);

Why does this need to exported for modules when the only users are
always built in?

> +
> +MODULE_DESCRIPTION("boot time tracker");
> +MODULE_LICENSE("GPL");

Why needs this a module description? This has always to be built in, no?

Copy and pasta from some boilerplate template is fine, but using brain
on what to paste is not optional.

But that's all irrelevant, because none of this is actually required in
the first place as there is existing infrastructure, which allows you to
gather most of that information already today.

Extending it to gain what you really want to achieve is trivial enough
when you actually start to look at the existing infrastructure instead
of blindly hacking some ill-defined mechanism into the kernel, which
relies on the assumption that a particular piece of hardware is
available and functional.

That assumption is not even true for ARM64 under all circumstances.

dmesg already exposes time stamps and while they might be coarse grained
until a sched clock is registered, you still can utilize that
registration:

--- a/kernel/time/sched_clock.c
+++ b/kernel/time/sched_clock.c
@@ -236,16 +236,14 @@ sched_clock_register(u64 (*read)(void),
 	/* 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: %u bits at %lu%cHz, resolution %lluns, wraps every %lluns 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)

That message provides you all the information you need for your pretty
printed postprocessing results by re-calculating all the other coarse
grained dmesg timestamps from there, no?

That obviously does not work on architectures which do no use the
sched_clock infrastructure. Some of them do not for a good reason, but
emitting the same information for them if anyone is interested is
trivial enough. And that's none of your problems.

If you really need some not yet existing dedicated time stamp in the
maze of dmesg, then add it unconditionlly and without introducing an
artifical subsystem which is of no value at all.

But I tell you that's not necessary at all. The points in dmesg are well
defined. Here is the relevant output on a arm64 machine:

[    0.000000] Linux version 6.17.0-rc1 ...
...
[    0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 3579139424256ns

which is missing the actual hardware value, but see above...

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?

So the [0.000008] timestamp happens exactly 1.0 seconds after power on.
At least to my understanding of basic math, but your favourite AI bot
might disagree with that.

So anything you need for your pretty printing boot record can be
retrieved from there without any magic 300 and 301 numbers.

Because there is another printk() which has been there forever:

[   11.651192] Run /init as init process

No?

Thanks,

        tglx

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Thomas Gleixner]

On Sun, Aug 24 2025 at 00:53, Thomas Gleixner wrote:
> So the [0.000008] timestamp happens exactly 1.0 seconds after power
> on.

Let me correct myself it's exactly: 1.000008 seconds after power on

Sorry for this fundamental mistake.

Thanks,

        tglx

(no subject)

[Kaiwan N Billimoria]

> 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.

Re:

[Kaiwan N Billimoria]

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.

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Kaiwan N Billimoria]

Resending, as the Subject was missing...

> 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.

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Thomas Gleixner]

On Tue, Sep 02 2025 at 12:32, Kaiwan N. Billimoria wrote:
> 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).

Looks about right.

> 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?

Under the assumption that nothing on the way resets the counter.

Thanks

        tglx

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Kaiwan N Billimoria]

Subject: Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp
> Under the assumption that nothing on the way resets the counter.
Ah. Is there any known component - within ROM/BL stages/kernel code - that does
this?
Forgive my asking, but if fine, will this (above-mentioned) patch be taken? So,
knowing that, we can proceed forward..

Thanks,
Kaiwan.

Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp

[Thomas Gleixner]

On Tue, Sep 02 2025 at 19:09, Kaiwan N. Billimoria wrote:
> Subject: Re: [RFC PATCH] time: introduce BOOT_TIME_TRACKER and minimal boot timestamp
>> Under the assumption that nothing on the way resets the counter.
> Ah. Is there any known component - within ROM/BL stages/kernel code - that does
> this?

How should I know? I'm not playing with this boot timing muck and yes,
some hardware counters can be reset by software...

> Forgive my asking, but if fine, will this (above-mentioned) patch be taken? So,
> knowing that, we can proceed forward..

Just send a patch with a proper justification and we take from there.

Thanks,

        tglx