Add tracing feature

Filelists.cmake

@@ -26,6 +26,8 @@ list(APPEND CMAKE_MODULE_PATH "${CMAKE_CURRENT_LIST_DIR}/admin/cmake")
 
 option(BUILD_UNIT_TESTS "Build unit tests" OFF)
 
+option(BUILD_TRACING "Build CTF tracing" OFF)
+
 add_compile_options(
     "$<$<COMPILE_LANG_AND_ID:CXX,Clang,GNU>:-O2;-g3;-Werror;-Wall;-Wextra;-Wvla;-Wno-deprecated-volatile>"
     # todo: enforce -Wunused-parameter
@@ -48,6 +50,13 @@ if (BUILD_UNIT_TESTS)
     enable_testing()
 endif ()
 
+if (BUILD_TRACING)
+    add_compile_definitions(TRACING=1)
+    if (TRACING_BUFFER_SIZE)
+        add_compile_definitions(TRACING_BUFFER_SIZE=${TRACING_BUFFER_SIZE})
+    endif ()
+endif ()
+
 set(INCLUDE_OPENBSW_LIBS_BSP
     ON
     CACHE BOOL "Include openbsw/libs/bsp/ in build")

doc/learning/overview.rst

@@ -18,3 +18,4 @@ Some simple lessons to get new users up and running.
     can/index
     uds/index
     hwio/index
+    tracing/index

doc/learning/tracing/index.rst

@@ -0,0 +1,107 @@
+.. _learning_tracing:
+
+Tracing
+=======
+
+Previous: :ref:`learning_hwio`
+
+The tracing feature collects scheduling events like task switches and interrupt entry and exit.
+This data can be used by tracing tools (e.g. `babeltrace2 <https://babeltrace.org/>`_)
+running on a host to visualize the kernel's inner workings and the behavior of its subsystems
+(e.g. when a task is switched in or out).
+
+The internal trace format is very efficient and usually uses a single 32 bit word per traced event.
+After the trace is done, the data is downloaded via a debugger and a post processing script is
+used to convert the traced data to other trace formats.
+
+Usage
+-----
+
+Before using the tracer it should be initialized. Initialization also clears the tracing buffer
+and ensures that existing data in the buffer is not confused with actual tracing data.
+
+.. code-block:: cpp
+
+	runtime::Tracer::init();
+
+When tracing is started, events are recorded into the tracing buffer.
+It is possible to stop tracing and restart it later. Note however, that the time span
+recorded between events before and after a longer pause might be wrong due to overflow
+of the underlying clock.
+
+.. code-block:: cpp
+
+	runtime::Tracer::start();
+	runtime::Tracer::stop();
+
+Once the trace buffer is full, the tracing will stop automatically.
+You can use the `init()` method to start over with an empty trace buffer.
+
+In order to trace their own custom events, users may use the method `traceUser(uint8_t usrIdx)`.
+The `usrIdx` argument can be used to distinguish different user events.
+
+.. code-block:: cpp
+
+	runtime::Tracer::traceUser(uint8_t usrIdx);
+
+Building
+--------
+
+Use build flag `-DBUILD_TRACING=ON` to turn tracing on and `-DTRACING_BUFFER_SIZE` to configure
+the tracing buffer size. For example, to build for S32K148EVB:
+
+.. code-block:: bash
+
+    cmake -B cmake-build-s32k148-tracing -S executables/referenceApp -DBUILD_TARGET_PLATFORM="S32K148EVB" \
+        -DBUILD_TRACING=ON -DTRACING_BUFFER_SIZE=65536 --toolchain ../../admin/cmake/ArmNoneEabi-gcc.cmake
+    cmake --build cmake-build-s32k148-tracing --target app.referenceApp -j
+
+The size of tracing buffer in RAM is configurable (TRACING_BUFFER_SIZE).
+If it is not provided in the cmake command, then the default value of 4096 bytes is configured.
+
+Analyzing the Data
+------------------
+
+Once the application is run, one can collect binary traces using gdb:
+
+.. code-block:: bash
+
+    (gdb) info address runtime::Tracer::_ramTraces
+    Symbol "runtime::Tracer::_ramTraces" is static storage at address 0x1ffee6bc.
+    (gdb) dump binary memory trace_file 0x1ffee6bc 0x1ffee6bc+65536
+
+This is an example of using trace_convert.py script to convert a binary trace to human-readable format.
+
+.. code-block:: bash
+
+    cp trace_file .
+    cp tools/tracing/trace_convert.py .
+    python3 ./trace_convert.py trace_file > output
+
+This is an example of using the babeltrace2 tool and source plugin bt_plugin_openbsw.py to convert
+a binary trace to human-readable format. The plugin is used to read trace data from ``trace_file``
+in described format and feed it into the babeltrace2 framework for conversion.
+
+.. code-block:: bash
+
+    cp trace_file .
+    cp tools/tracing/trace_convert.py .
+    cp tools/tracing/bt_plugin_openbsw.py .
+    babeltrace2 --plugin-path . -c source.openbsw.OpenBSWSource --params 'inputs=["trace_file"]' > output
+
+This is an example output:
+
+.. code-block:: none
+
+    [01:00:00.009286800] (+?.?????????) thread_switched_in: { id = 8 }
+    [01:00:00.009307300] (+0.000020500) thread_switched_out: { id = 8 }
+    [01:00:00.009312387] (+0.000005087) thread_switched_in: { id = 7 }
+    [01:00:00.009321662] (+0.000009275) thread_switched_out: { id = 7 }
+    [01:00:00.009325687] (+0.000004025) thread_switched_in: { id = 6 }
+    [01:00:00.009459762] (+0.000134075) thread_switched_out: { id = 6 }
+    [01:00:00.009465125] (+0.000005363) thread_switched_in: { id = 5 }
+    [01:00:00.009473562] (+0.000008437) thread_switched_out: { id = 5 }
+    [01:00:00.009478112] (+0.000004550) thread_switched_in: { id = 4 }
+    [01:00:00.009486075] (+0.000007963) thread_switched_out: { id = 4 }
+    [01:00:00.009490187] (+0.000004112) thread_switched_in: { id = 3 }
+    [01:00:00.009500287] (+0.000010100) thread_switched_out: { id = 3 }

executables/referenceApp/application/src/app/app.cpp

@@ -10,6 +10,9 @@
 #include "systems/RuntimeSystem.h"
 #include "systems/SafetySystem.h"
 #include "systems/SysAdminSystem.h"
+#ifdef TRACING
+#include "runtime/Tracer.h"
+#endif
 
 #include <app/appConfig.h>
 
@@ -132,6 +135,10 @@ void run()
     printf("hello\r\n");
     staticInit();
     AsyncAdapter::init();
+#if TRACING
+    runtime::Tracer::init();
+    runtime::Tracer::start();
+#endif
 
     /* runlevel 1 */
     ::platform::platformLifecycleAdd(lifecycleManager, 1U);

executables/referenceApp/application/src/systems/DemoSystem.cpp

@@ -11,6 +11,9 @@
 #include "app/DemoLogger.h"
 
 #include <bsp/SystemTime.h>
+#ifdef TRACING
+#include "runtime/Tracer.h"
+#endif
 
 #include <estd/big_endian.h>
 #ifdef PLATFORM_SUPPORT_CAN
@@ -126,6 +129,10 @@ void DemoSystem::cyclic()
         }
     }
 #endif
+
+#if TRACING
+    runtime::Tracer::traceUser(42);
+#endif
 }
 
 } // namespace systems

executables/referenceApp/platforms/s32k148evb/bspConfiguration/src/bsp/SystemTimer/SystemTimer.cpp

@@ -21,7 +21,8 @@ struct
     uint64_t ticks; // Main ticks counter, never overflows
     uint32_t lastDwt;
     uint32_t dwtTicksRatio;
-} state = {0, 0, DWT_FREQ_MHZ_RUN / TICK_FREQ_MHZ};
+    uint32_t dwtFreqMhz;
+} state = {0, 0, DWT_FREQ_MHZ_RUN / TICK_FREQ_MHZ, DWT_FREQ_MHZ_RUN};
 
 // DWT registers (refer to ARMv7-M architecture reference manual)
 uint32_t volatile& DWT_CTRL   = *reinterpret_cast<uint32_t volatile*>(0xE0001000U);
@@ -59,12 +60,17 @@ void initSystemTimer()
     state.ticks         = 0; // General ticks counter, never overflows
     state.lastDwt       = 0;
     state.dwtTicksRatio = DWT_FREQ_MHZ_RUN / TICK_FREQ_MHZ;
+    state.dwtFreqMhz    = DWT_FREQ_MHZ_RUN;
 }
 
 void initSystemTimerHelper(bool const sleep)
 {
     (void)updateTicks();
-    state.dwtTicksRatio = (sleep ? DWT_FREQ_MHZ_IDLE : DWT_FREQ_MHZ_RUN) / TICK_FREQ_MHZ;
+    {
+        const ESR_UNUSED interrupts::SuspendResumeAllInterruptsScopedLock lock;
+        state.dwtFreqMhz    = sleep ? DWT_FREQ_MHZ_IDLE : DWT_FREQ_MHZ_RUN;
+        state.dwtTicksRatio = state.dwtFreqMhz / TICK_FREQ_MHZ;
+    }
 }
 
 uint64_t getSystemTicks(void) { return updateTicks(); }
@@ -88,6 +94,14 @@ uint64_t systemTicksToTimeUs(uint64_t const ticks) { return ticks / TICK_FREQ_MH
 
 uint64_t systemTicksToTimeNs(uint64_t const ticks) { return ticks * 1000U / TICK_FREQ_MHZ; }
 
+uint32_t getFastTicks(void) { return DWT_CYCCNT; }
+
+uint32_t getFastTicksPerSecond(void)
+{
+    const ESR_UNUSED interrupts::SuspendResumeAllInterruptsScopedLock lock;
+    return state.dwtFreqMhz * 1000000;
+}
+
 void sysDelayUs(uint32_t const delay)
 {
     uint64_t const start = getSystemTimeUs();

libs/bsw/bsp/include/bsp/timer/SystemTimer.h

@@ -64,6 +64,19 @@ uint64_t systemTicksToTimeUs(uint64_t ticks);
  */
 uint64_t systemTicksToTimeNs(uint64_t ticks);
 
+/**
+ * Returns a tick count which can be read very efficiently.
+ *
+ * This is a 32bit value which wraps around after reaching its maximum.
+ * Use getFastTicksPerSecond() to get the tick resolution.
+ */
+uint32_t getFastTicks(void);
+
+/**
+ * Returns the number of fast ticks per second.
+ */
+uint32_t getFastTicksPerSecond();
+
 void initSystemTimer();
 /*
  * Returns project dependent TickTime

libs/bsw/runtime/CMakeLists.txt

@@ -1,5 +1,9 @@
 add_library(runtime src/runtime/StatisticsWriter.cpp)
 
+if (BUILD_TRACING)
+    target_sources(runtime PRIVATE src/runtime/Tracer.cpp)
+endif ()
+
 target_include_directories(runtime PUBLIC include)
 
 target_link_libraries(runtime PUBLIC async bsp estd util)

libs/bsw/runtime/include/runtime/RuntimeMonitor.h

@@ -11,6 +11,9 @@
 #include "runtime/RuntimeStack.h"
 #include "runtime/SimpleRuntimeEntry.h"
 #include "runtime/StatisticsContainer.h"
+#ifdef TRACING
+#include "runtime/Tracer.h"
+#endif
 
 #include <estd/slice.h>
 
@@ -87,6 +90,9 @@ class RuntimeMonitor
     void enterTask(size_t const taskIdx)
     {
         ::async::LockType const lock;
+#ifdef TRACING
+        Tracer::traceThreadSwitchedIn(static_cast<uint8_t>(taskIdx));
+#endif
         uint32_t const timestamp = getSystemTicks32Bit();
         _lastEnterTaskTimestamp  = timestamp;
         _contextStack.pushEntry(_taskStatistics.getEntry(taskIdx), timestamp);
@@ -95,20 +101,29 @@ class RuntimeMonitor
     void leaveTask(size_t const taskIdx)
     {
         ::async::LockType const lock;
+#ifdef TRACING
+        Tracer::traceThreadSwitchedOut(static_cast<uint8_t>(taskIdx));
+#endif
         uint32_t const timestamp = getSystemTicks32Bit();
         _contextStack.popEntry(_taskStatistics.getEntry(taskIdx), timestamp);
     }
 
     void enterIsrGroup(size_t const isrGroupIdx)
     {
         ::async::LockType const lock;
+#ifdef TRACING
+        Tracer::traceIsrEnter(static_cast<uint8_t>(isrGroupIdx));
+#endif
         uint32_t const timestamp = getSystemTicks32Bit();
         _contextStack.pushEntry(_isrGroupStatistics.getEntry(isrGroupIdx), timestamp);
     }
 
     void leaveIsrGroup(size_t const isrGroupIdx)
     {
         ::async::LockType const lock;
+#ifdef TRACING
+        Tracer::traceIsrExit(static_cast<uint8_t>(isrGroupIdx));
+#endif
         uint32_t const timestamp = getSystemTicks32Bit();
         _contextStack.popEntry(_isrGroupStatistics.getEntry(isrGroupIdx), timestamp);
     }

libs/bsw/runtime/include/runtime/Tracer.h

@@ -0,0 +1,56 @@
+// Copyright 2025 Accenture.
+
+#pragma once
+
+#include "FreeRTOSConfig.h"
+
+#include <platform/estdint.h>
+
+namespace runtime
+{
+#ifndef TRACING_BUFFER_SIZE
+#define TRACING_BUFFER_SIZE 4096
+#endif
+
+class Tracer
+{
+public:
+    Tracer();
+
+    static void init();
+    static void start();
+    static void stop();
+
+    static void traceThreadSwitchedOut(uint8_t const taskIdx);
+    static void traceThreadSwitchedIn(uint8_t const taskIdx);
+    static void traceIsrEnter(uint8_t const isrIdx);
+    static void traceIsrExit(uint8_t const isrIdx);
+    static void traceUser(uint8_t const usrIdx);
+
+    static bool bufferFull();
+
+private:
+    enum Event
+    {
+        EVENT_THREAD_SWITCHED_OUT = 0x0,
+        EVENT_THREAD_SWITCHED_IN  = 0x1,
+        EVENT_ISR_ENTER           = 0x2,
+        EVENT_ISR_EXIT            = 0x3,
+        EVENT_USER                = 0x4,
+    };
+
+    static constexpr uint32_t TRACING_BUFFER_WORD_SIZE = TRACING_BUFFER_SIZE / sizeof(uint32_t);
+
+    static constexpr uint32_t RELATIVE_CYCLES_WIDTH = 20;
+    static constexpr uint32_t RELATIVE_CYCLES_MAX   = (1 << RELATIVE_CYCLES_WIDTH) - 1;
+
+    static void traceEvent(Event const& event, uint8_t const& id);
+
+private:
+    static uint32_t _ramTraces[TRACING_BUFFER_WORD_SIZE];
+    static bool _running;
+    static uint32_t _pos;
+    static uint32_t _prevCycles;
+};
+
+} // namespace runtime