tests/benchmarks: fix BOOT_TIME_MEASUREMENT

The boot time measurement sample was giving bogus values on x86: an
assumption was made that the system timer is in sync with the CPU TSC,
which is not the case on most x86 boards.

Boot time measurements are no longer permitted unless the timer source
is the local APIC. To avoid issues of TSC scaling, the startup datum
has been forced to 0, which is in line with the ARM implementation
(which is the only other platform which supports this feature).

Cleanups along the way:

As the datum is now assumed zero, some variables are removed and
calculations simplified. The global variables involved in boot time
measurements are moved to the kernel.h header rather than being
redeclared in every place they are referenced. Since none of the
measurements actually use 64-bit precision, the samples are reduced
to 32-bit quantities.

In addition, this feature has been enabled in long mode.

Fixes: #19144

Signed-off-by: Charles E. Youse <charles.youse@intel.com>

arch/arm/core/prep_c.c

@@ -155,9 +155,6 @@ extern FUNC_NORETURN void z_cstart(void);
  *
  * @return N/A
  */
-#ifdef CONFIG_BOOT_TIME_MEASUREMENT
-	extern u64_t __start_time_stamp;
-#endif
 void _PrepC(void)
 {
 	relocate_vector_table();
@@ -166,9 +163,6 @@ void _PrepC(void)
 	z_data_copy();
 #if defined(CONFIG_ARMV7_R) && defined(CONFIG_INIT_STACKS)
 	init_stacks();
-#endif
-#ifdef CONFIG_BOOT_TIME_MEASUREMENT
-	__start_time_stamp = 0U;
 #endif
 	z_IntLibInit();
 	z_cstart();

arch/x86/core/cpuhalt.c

@@ -7,10 +7,6 @@
 #include <debug/tracing.h>
 #include <arch/cpu.h>
 
-#ifdef CONFIG_BOOT_TIME_MEASUREMENT
-extern u64_t __idle_time_stamp;  /* timestamp when CPU went idle */
-#endif
-
 /**
  *
  * @brief Power save idle routine
@@ -26,7 +22,7 @@ void k_cpu_idle(void)
 {
 	z_sys_trace_idle();
 #if defined(CONFIG_BOOT_TIME_MEASUREMENT)
-	__idle_time_stamp = (u64_t)k_cycle_get_32();
+	__idle_time_stamp = k_cycle_get_32();
 #endif
 
 	__asm__ volatile (

arch/x86/core/ia32/crt0.S

@@ -37,10 +37,6 @@
 	GDATA(_sse_mxcsr_default_value)
 #endif
 
-#if defined(CONFIG_BOOT_TIME_MEASUREMENT)
-	GDATA(__start_time_stamp)
-#endif
-
 #ifdef CONFIG_SYS_POWER_DEEP_SLEEP_STATES
 	GTEXT(_sys_resume_from_deep_sleep)
 #endif
@@ -71,15 +67,12 @@ SECTION_FUNC(TEXT_START, __start)
 
 #ifdef CONFIG_BOOT_TIME_MEASUREMENT
 	/*
-	 * Record BootTime from start of Kernel.
-	 * Store value temporarily in Register edi & esi and
-         * write to memory once memory access is allowed.
-         * That is, once the data segment register has been setup to access
-         * the .data/.rodata/.bss section of the linked image.
+	 * Reset the TSC to 0, since that's the datum for boot metrics.
 	 */
-        rdtsc
-        mov  %eax, %esi			/* low  value */
-        mov  %edx, %edi			/* high value */
+	xorl	%eax, %eax
+	xorl	%edx, %edx
+	movl	$X86_TIME_STAMP_COUNTER_MSR, %ecx
+	wrmsr
 #endif
 
 	/* Enable write-back caching by clearing the NW and CD bits */
@@ -122,14 +115,6 @@ __csSet:
 #endif /* CONFIG_SET_GDT */
 
 
-#ifdef CONFIG_BOOT_TIME_MEASUREMENT
-	/*
-	 * Store rdtsc result from temporary regiter ESI & EDI into memory.
-	 */
-        mov  %esi, __start_time_stamp  	/* low  value */
-        mov  %edi, __start_time_stamp+4    	/* high value */
-#endif
-
 #if !defined(CONFIG_FLOAT)
 	/*
 	 * Force an #NM exception for floating point instructions

arch/x86/core/intel64/locore.S

@@ -31,8 +31,16 @@ __start:
 1:
 #endif
 
+	/* FIXME: ...resetting TSC here is common to IA32 and Intel64... */
 	/* FIXME: ...disabling the PICs is common to IA32 and Intel64... */
 
+#ifdef CONFIG_BOOT_TIME_MEASUREMENT
+	xorl %eax, %eax
+	xorl %edx, %edx
+	movl $X86_TIME_STAMP_COUNTER_MSR, %ecx
+	wrmsr
+#endif
+
 #ifdef CONFIG_PIC_DISABLE
 	movb $0xff, %al
 	outb %al, $0x21

include/arch/x86/msr.h

@@ -10,6 +10,8 @@
  * Model specific registers (MSR).  Access with z_x86_msr_read/write().
  */
 
+#define X86_TIME_STAMP_COUNTER_MSR	0x00000010
+
 #define X86_SPEC_CTRL_MSR		0x00000048
 #define X86_SPEC_CTRL_MSR_IBRS		BIT(0)
 #define X86_SPEC_CTRL_MSR_SSBD		BIT(2)

include/kernel.h

@@ -23,6 +23,11 @@
 extern "C" {
 #endif
 
+#ifdef CONFIG_BOOT_TIME_MEASUREMENT
+extern u32_t __main_time_stamp; /* timestamp when main task starts */
+extern u32_t __idle_time_stamp; /* timestamp when CPU goes idle */
+#endif
+
 /**
  * @brief Kernel APIs
  * @defgroup kernel_apis Kernel APIs

kernel/idle.c

@@ -140,9 +140,9 @@ void idle(void *unused1, void *unused2, void *unused3)
 #ifdef CONFIG_BOOT_TIME_MEASUREMENT
 	/* record timestamp when idling begins */
 
-	extern u64_t __idle_time_stamp;
+	extern u32_t __idle_time_stamp;
 
-	__idle_time_stamp = (u64_t)k_cycle_get_32();
+	__idle_time_stamp = k_cycle_get_32();
 #endif
 
 #ifdef CONFIG_SMP

kernel/init.c

@@ -66,9 +66,8 @@ LOG_MODULE_REGISTER(os);
 /* boot time measurement items */
 
 #ifdef CONFIG_BOOT_TIME_MEASUREMENT
-u64_t __noinit __start_time_stamp; /* timestamp when kernel starts */
-u64_t __noinit __main_time_stamp;  /* timestamp when main task starts */
-u64_t __noinit __idle_time_stamp;  /* timestamp when CPU goes idle */
+u32_t __noinit __main_time_stamp;  /* timestamp when main task starts */
+u32_t __noinit __idle_time_stamp;  /* timestamp when CPU goes idle */
 #endif
 
 /* init/main and idle threads */
@@ -284,10 +283,7 @@ static void bg_thread_main(void *unused1, void *unused2, void *unused3)
 #endif
 
 #ifdef CONFIG_BOOT_TIME_MEASUREMENT
-	/* record timestamp for kernel's _main() function */
-	extern u64_t __main_time_stamp;
-
-	__main_time_stamp = (u64_t)k_cycle_get_32();
+	__main_time_stamp = k_cycle_get_32();
 #endif
 
 	extern void main(void);

subsys/debug/Kconfig

@@ -9,12 +9,10 @@
 menu "System Monitoring Options"
 
 config BOOT_TIME_MEASUREMENT
-	bool "Boot time measurements [EXPERIMENTAL]"
+	bool "Boot time measurements"
+	depends on ARCH_POSIX || ARM || (X86 && APIC_TIMER && APIC_TIMER_TSC)
 	help
-	  This option enables the recording of timestamps during system start
-	  up. The global variable __start_time_stamp records the time kernel
-	  begins executing, while __main_time_stamp records when main() begins
-	  executing, and __idle_time_stamp records when the CPU becomes idle.
+	  This option enables the recording of timestamps during system boot.
 
 config STATS
 	bool "Statistics support"

tests/benchmarks/boot_time/src/main.c

@@ -10,33 +10,22 @@
  * @brief Measure boot time
  *
  * Measuring the boot time
- *  1. From reset to kernel's __start
- *  2. From __start to main()
- *  3. From __start to task
- *  4. From __start to idle
+ *  1. From __start to main()
+ *  2. From __start to task
+ *  3. From __start to idle
  */
 
 #include <zephyr.h>
-
 #include <tc_util.h>
 
-/* externs */
-extern u64_t __start_time_stamp;    /* timestamp when kernel begins executing */
-extern u64_t __main_time_stamp;     /* timestamp when main() begins executing */
-extern u64_t __idle_time_stamp;     /* timestamp when CPU went idle */
-
 void main(void)
 {
-	u64_t task_time_stamp;      /* timestamp at beginning of first task  */
-	u64_t _start_us;     /* being of __start timestamp in us	 */
-	u64_t main_us;       /* begin of main timestamp in us	 */
-	u64_t task_us;       /* begin of task timestamp in us	 */
-	u64_t s_main_time_stamp;    /* __start->main timestamp		 */
-	u64_t s_task_time_stamp;    /*__start->task timestamp		 */
-	u64_t idle_us;       /* begin of idle timestamp in us	 */
-	u64_t s_idle_time_stamp;    /*__start->idle timestamp		 */
+	u32_t task_time_stamp;	/* timestamp at beginning of first task */
+	u32_t main_us;		/* begin of main timestamp in us */
+	u32_t task_us;		/* begin of task timestamp in us */
+	u32_t idle_us;		/* begin of idle timestamp in us */
 
-	task_time_stamp = (u64_t)k_cycle_get_32();
+	task_time_stamp = k_cycle_get_32();
 
 	/*
 	 * Go to sleep for 1 tick in order to timestamp when idle thread halts.
@@ -45,37 +34,20 @@ void main(void)
 
 	int freq = sys_clock_hw_cycles_per_sec() / 1000000;
 
-	_start_us  =  __start_time_stamp / freq;
-	s_main_time_stamp =  __main_time_stamp - __start_time_stamp;
-	main_us    =  s_main_time_stamp / freq;
-	s_task_time_stamp =  task_time_stamp   - __start_time_stamp;
-	task_us    =  s_task_time_stamp / freq;
-	s_idle_time_stamp =  __idle_time_stamp - __start_time_stamp;
-	idle_us    =  s_idle_time_stamp / freq;
+	main_us = __main_time_stamp / freq;
+	task_us = task_time_stamp / freq;
+	idle_us = __idle_time_stamp / freq;
 
-	/* Indicate start for sanity test suite */
 	TC_START("Boot Time Measurement");
-
-	/* Only print lower 32bit of time result */
-	TC_PRINT("Boot Result: Clock Frequency: %d MHz\n",
-		 freq);
-	TC_PRINT("__start       : %u cycles, %u us\n",
-		 (u32_t)(__start_time_stamp & 0xFFFFFFFFULL),
-		 (u32_t) (_start_us  & 0xFFFFFFFFULL));
-	TC_PRINT("_start->main(): %u cycles, %u us\n",
-		 (u32_t)(s_main_time_stamp & 0xFFFFFFFFULL),
-		 (u32_t)  (main_us  & 0xFFFFFFFFULL));
-	TC_PRINT("_start->task  : %u cycles, %u us\n",
-		 (u32_t)(s_task_time_stamp & 0xFFFFFFFFULL),
-		 (u32_t)  (task_us  & 0xFFFFFFFFULL));
-	TC_PRINT("_start->idle  : %u cycles, %u us\n",
-		 (u32_t)(s_idle_time_stamp & 0xFFFFFFFFULL),
-		 (u32_t)  (idle_us  & 0xFFFFFFFFULL));
-
+	TC_PRINT("Boot Result: Clock Frequency: %d MHz\n", freq);
+	TC_PRINT("_start->main(): %u cycles, %u us\n", __main_time_stamp,
+						       main_us);
+	TC_PRINT("_start->task  : %u cycles, %u us\n", task_time_stamp,
+						       task_us);
+	TC_PRINT("_start->idle  : %u cycles, %u us\n", __idle_time_stamp,
+						       idle_us);
 	TC_PRINT("Boot Time Measurement finished\n");
 
-	/* for sanity regression test utility. */
 	TC_END_RESULT(TC_PASS);
 	TC_END_REPORT(TC_PASS);
-
 }