Add kernel entry and exit tracing

Log entries into and exits out of the kernel into the debug log buffer. Co-authored-by: Curtis Millar <[email protected]> Signed-off-by: Axel Heider <[email protected]>
axel-h · Dec 5, 2021 · 6a4f7c7 · 6a4f7c7
1 parent 3850695
commit 6a4f7c7
Show file tree

Hide file tree

Showing 12 changed files with 79 additions and 19 deletions.
diff --git a/config.cmake b/config.cmake
@@ -393,6 +393,13 @@ config_option(
     DEFAULT_DISABLED OFF
 )
 
+config_option(
+    KernelTraceEntries KERNEL_TRACE_ENTRIES "Enable tracing of kernel entry and exit"
+    DEFAULT ON
+    DEPENDS "KernelEventTracing"
+    DEFAULT_DISABLED OFF
+)
+
 # CONFIG_ENABLE_KERNEL_LOG_BUFFER is set automatically if a feature is used that
 # needs the kernel log buffer.
 if(KernelBenchmarksTrackKernelEntries OR KernelBenchmarksTracepoints OR KernelEventTracing)

diff --git a/include/arch/arm/arch/benchmark.h b/include/arch/arm/arch/benchmark.h
@@ -8,7 +8,7 @@
 
 #include <config.h>
 
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 
 #include <types.h>
 #include <armv/benchmark.h>
@@ -54,4 +54,4 @@ static inline void benchmark_arch_utilisation_reset(void)
 }
 #endif /* CONFIG_BENCHMARK_TRACK_UTILISATION */
 
-#endif /* CONFIG_ENABLE_BENCHMARKS */
+#endif /* CONFIG_ENABLE_BENCHMARKS || CONFIG_KERNEL_TRACE_ENTRIES */
diff --git a/include/arch/arm/armv/armv7-a/armv/benchmark.h b/include/arch/arm/armv/armv7-a/armv/benchmark.h
@@ -6,7 +6,7 @@
 
 #pragma once
 
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 #include <config.h>
 
 #define PMCR "p15, 0, %0, c9, c12, 0"
@@ -29,5 +29,5 @@ static inline void armv_handleOverflowIRQ(void)
     word_t val = BIT(CCNT_INDEX);
     MCR(PMOVSR, val);
 }
-#endif /* CONFIG_ENABLE_BENCHMARKS */
+#endif /* CONFIG_ENABLE_BENCHMARKS || CONFIG_KERNEL_TRACE_ENTRIES */
 
diff --git a/include/arch/arm/armv/armv8-a/64/armv/benchmark.h b/include/arch/arm/armv/armv8-a/64/armv/benchmark.h
@@ -7,7 +7,7 @@
 #pragma once
 
 #include <config.h>
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 
 #define CCNT "PMCCNTR_EL0"
 #define PMCR "PMCR_EL0"
@@ -30,5 +30,5 @@ static inline void armv_handleOverflowIRQ(void)
     MSR(PMOVSR, val);
 }
 
-#endif /* CONFIG_ENABLE_BENCHMARKS */
+#endif /* CONFIG_ENABLE_BENCHMARKS || CONFIG_KERNEL_TRACE_ENTRIES */
 
diff --git a/include/arch/riscv/arch/benchmark.h b/include/arch/riscv/arch/benchmark.h
@@ -9,7 +9,7 @@
 
 #include <config.h>
 
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 
 #include <types.h>
 #include <arch/object/structures.h>
@@ -27,4 +27,4 @@ static inline void benchmark_arch_utilisation_reset(void)
 }
 #endif /* CONFIG_BENCHMARK_TRACK_UTILISATION */
 
-#endif /* CONFIG_ENABLE_BENCHMARK */
+#endif /* CONFIG_ENABLE_BENCHMARK || CONFIG_KERNEL_TRACE_ENTRIES */
diff --git a/include/arch/x86/arch/benchmark.h b/include/arch/x86/arch/benchmark.h
@@ -8,7 +8,7 @@
 
 #include <config.h>
 
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 
 #include <types.h>
 

diff --git a/include/benchmark/log.h b/include/benchmark/log.h
@@ -68,6 +68,31 @@ static inline void debugLog_Function(None)(void)
     logBuffer_reserve(None);
 }
 
+/* Log a kernel entry */
+static inline void debugLog_Function(Entry)(void)
+{
+#ifdef CONFIG_KERNEL_TRACE_ENTRIES
+    seL4_Log_Type(Entry) *event = logBuffer_reserve(Entry);
+    if (event != NULL) {
+        event->header.data = CURRENT_CPU_INDEX();
+        event->timestamp = timestamp();
+    }
+#endif /* CONFIG_KERNEL_TRACE_ENTRIES */
+}
+
+/* Log a kernel exit */
+static inline void debugLog_Function(Exit)(void)
+{
+#ifdef CONFIG_KERNEL_TRACE_ENTRIES
+    seL4_Log_Type(Exit) *event = logBuffer_reserve(Exit);
+    if (event != NULL) {
+        event->header.data = CURRENT_CPU_INDEX();
+        event->timestamp = timestamp();
+    }
+#endif /* CONFIG_KERNEL_TRACE_ENTRIES */
+}
+
+
 #else /* not CONFIG_KERNEL_EVENT_TRACING */
 
 /* With logging disabled, any logging functions become no-ops */

diff --git a/include/kernel/traps.h b/include/kernel/traps.h
@@ -18,7 +18,7 @@
 static inline void c_entry_hook(void)
 {
     arch_c_entry_hook();
-#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION)
+#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION) || defined(KERNEL_TRACE_ENTRIES)
     benchmark_track_start();
 #endif
 }
@@ -29,7 +29,7 @@ static inline void c_entry_hook(void)
  * in C before leaving the kernel */
 static inline void c_exit_hook(void)
 {
-#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION)
+#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION) || defined(KERNEL_TRACE_ENTRIES)
     benchmark_track_exit();
 #endif
     arch_c_exit_hook();

diff --git a/libsel4/include/sel4/log.h b/libsel4/include/sel4/log.h
@@ -74,15 +74,30 @@ typedef struct {
 
 /* Event type identifiers */
 enum {
-    seL4_Log_TypeId(None),
-    seL4_NumLogTypeIds,
+    seL4_Log_TypeId(None)   = 0,
+    seL4_Log_TypeId(Entry)  = 1,
+    seL4_Log_TypeId(Exit)   = 2,
+    /* add more txpes here */
+    seL4_NumLogTypeIds      = 3,
 };
 
 /* Log an empty event */
 typedef struct {
     seL4_LogEvent header;
 } seL4_Log_Type(None);
 
+/* Entry into kernel */
+typedef struct {
+    seL4_LogEvent header;   /* Header data contains core ID */
+    seL4_Uint64 timestamp;  /* Timestamp from cycle counter */
+} seL4_Log_Type(Entry);
+
+/* Exit from kernel */
+typedef struct {
+    seL4_LogEvent header;   /* Header data contains core ID */
+    seL4_Uint64 timestamp;  /* Timestamp from cycle counter */
+} seL4_Log_Type(Exit);
+
 /*
  * Reading information from log events
  * ===================================
@@ -94,8 +109,10 @@ typedef struct {
 /* Get the length of an event type */
 static inline seL4_Word seL4_LogType_length(seL4_Word type)
 {
-    static seL4_Word type_lengths[seL4_NumLogTypeIds] = {
+    static const seL4_Word type_lengths[seL4_NumLogTypeIds] = {
         [seL4_Log_TypeId(None)] = seL4_Log_Length(None),
+        [seL4_Log_TypeId(Entry)] = seL4_Log_Length(Entry),
+        [seL4_Log_TypeId(Exit)] = seL4_Log_Length(Exit),
     };
 
     if (type >= seL4_NumLogTypeIds) {

diff --git a/src/arch/arm/benchmark/benchmark.c b/src/arch/arm/benchmark/benchmark.c
@@ -16,6 +16,7 @@
 UP_STATE_DEFINE(uint64_t, ccnt_num_overflows);
 #endif /* CONFIG_ARM_ENABLE_PMU_OVERFLOW_INTERRUPT */
 
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
 void arm_init_ccnt(void)
 {
 
@@ -31,4 +32,5 @@ void arm_init_ccnt(void)
     armv_enableOverflowIRQ();
 #endif /* CONFIG_ARM_ENABLE_PMU_OVERFLOW_INTERRUPT */
 }
-#endif
+
+#endif /* CONFIG_ENABLE_BENCHMARKS || CONFIG_KERNEL_TRACE_ENTRIES */
diff --git a/src/arch/arm/kernel/boot.c b/src/arch/arm/kernel/boot.c
@@ -227,9 +227,9 @@ BOOT_CODE static bool_t init_cpu(void)
 
     cpu_initLocalIRQController();
 
-#ifdef CONFIG_ENABLE_BENCHMARKS
+#if defined(CONFIG_ENABLE_BENCHMARKS) || defined(CONFIG_KERNEL_TRACE_ENTRIES)
     arm_init_ccnt();
-#endif /* CONFIG_ENABLE_BENCHMARKS */
+#endif /* CONFIG_ENABLE_BENCHMARKS || CONFIG_KERNEL_TRACE_ENTRIES */
 
     /* Export selected CPU features for access by PL0 */
     armv_init_user_access();

diff --git a/src/benchmark/benchmark.c b/src/benchmark/benchmark.c
@@ -36,14 +36,19 @@ bool_t ksStarted[CONFIG_MAX_NUM_TRACE_POINTS];
 
 kernel_entry_t ksKernelEntry; /* ToDo: make this core specific */
 
-#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION)
+#if defined(CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES) || defined(CONFIG_BENCHMARK_TRACK_UTILISATION) || defined(KERNEL_TRACE_ENTRIES)
 
 /* ToDo: make these core specific */
 timestamp_t ksTimestampEnter;
 
 void benchmark_track_start(void)
 {
     ksTimestampEnter = timestamp();
+
+#ifdef KERNEL_TRACE_ENTRIES
+    debugLog(Entry);
+#endif
+
 }
 
 void benchmark_track_exit(void)
@@ -52,6 +57,10 @@ void benchmark_track_exit(void)
     assert(ksTimestampExit >= ksTimestampEnter);
     timestamp_t duration = ksTimestampExit - ksTimestampEnter;
 
+#ifdef KERNEL_TRACE_ENTRIES
+    debugLog(Exit);
+#endif
+
 #ifdef CONFIG_BENCHMARK_TRACK_UTILISATION
 
     if (likely(NODE_STATE(benchmark_log_utilisation_enabled))) {
@@ -90,7 +99,7 @@ void benchmark_track_exit(void)
 
 }
 
-#endif /* CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES || CONFIG_BENCHMARK_TRACK_UTILISATION */
+#endif /* CONFIG_BENCHMARK_TRACK_KERNEL_ENTRIES || CONFIG_BENCHMARK_TRACK_UTILISATION || KERNEL_TRACE_ENTRIES */
 
 void benchmark_debug_syscall_start(word_t cptr, word_t msgInfo, word_t syscall)
 {