Trace wakeup latency

cactusdynamics · Sep 17, 2023 · 8bc07ee · 8bc07ee
1 parent a9de136
commit 8bc07ee
Show file tree

Hide file tree

Showing 3 changed files with 22 additions and 9 deletions.
diff --git a/examples/tracing_example/main.cc b/examples/tracing_example/main.cc
@@ -66,7 +66,8 @@ int main() {
   thread_config.cpu_affinity = std::vector<size_t>{2};
   thread_config.SetFifoScheduler(80);
 
-  thread_config.tracer_config.trace_sleep = true;
+  // thread_config.tracer_config.trace_sleep = true;
+  thread_config.tracer_config.trace_wakeup_latency = true;
 
   cactus_rt::AppConfig app_config;
   app_config.tracer_config.trace_aggregator_cpu_affinity = {1};

diff --git a/include/cactus_rt/config.h b/include/cactus_rt/config.h
@@ -91,6 +91,13 @@ struct ThreadTracerConfig {
    * Enabling this will cause a slight performance overhead when trace session is started.
    */
   bool trace_sleep = false;
+
+  /**
+   * @brief Trace the wakeup latency between when the thread should have woken up and when it actually woke up.
+   *
+   * Enabling this will cause a slight performance overhead when trace session is started.
+   */
+  bool trace_wakeup_latency = false;
 };
 
 /**

diff --git a/src/cactus_rt/cyclic_thread.cc b/src/cactus_rt/cyclic_thread.cc
@@ -7,34 +7,38 @@ namespace cactus_rt {
 void CyclicThread::Run() noexcept {
   // TODO: change this from CLOCK_MONOTONIC to CLOCK_MONOTONIC_RAW/CLOCK_BOOTTIME?
   clock_gettime(CLOCK_MONOTONIC, &next_wakeup_time_);
-  int64_t loop_start, loop_end, should_have_woken_up_at;
+  int64_t next_wakeup_time_ns = next_wakeup_time_.tv_sec * 1'000'000'000 + next_wakeup_time_.tv_nsec;
+
+  int64_t loop_start, loop_end;
   int64_t wakeup_latency, loop_latency;
 
   const auto tracer_config = this->Config().tracer_config;
 
   while (!this->StopRequested()) {
-    should_have_woken_up_at = next_wakeup_time_.tv_nsec * 1'000'000'000 + next_wakeup_time_.tv_nsec;
     loop_start = NowNs();
-    wakeup_latency = loop_start - should_have_woken_up_at;
+    if (tracer_config.trace_wakeup_latency) {
+      Tracer().StartSpan("WakeupLatency", "cactusrt", next_wakeup_time_ns);
+      Tracer().EndSpan(loop_start);
+    }
 
-    bool should_stop;
     if (tracer_config.trace_loop) {
-      Tracer().StartSpan("CyclicThread::Loop", "cactusrt", loop_start);
+      Tracer().StartSpan("Loop", "cactusrt", loop_start);
     }
 
-    should_stop = Loop(loop_start - Thread::StartMonotonicTimeNs());
+    bool should_stop = Loop(loop_start - Thread::StartMonotonicTimeNs());
 
     loop_end = NowNs();
 
     if (tracer_config.trace_loop) {
       Tracer().EndSpan(loop_end);
     }
 
+    wakeup_latency = loop_start - next_wakeup_time_ns;
     loop_latency = loop_end - loop_start;
     TrackLatency(wakeup_latency, loop_latency);
 
     if (tracer_config.trace_overrun && static_cast<uint64_t>(loop_latency) >= period_ns_) {
-      Tracer().InstantEvent("CyclicThread::LoopOverrun", "cactusrt");
+      Tracer().InstantEvent("LoopOverrun", "cactusrt");
 
       LOG_WARNING_LIMIT(
         std::chrono::milliseconds(100),
@@ -50,9 +54,10 @@ void CyclicThread::Run() noexcept {
     }
 
     next_wakeup_time_ = AddTimespecByNs(next_wakeup_time_, static_cast<int64_t>(period_ns_));
+    next_wakeup_time_ns = next_wakeup_time_.tv_sec * 1'000'000'000 + next_wakeup_time_.tv_nsec;
 
     {
-      auto span = Tracer().WithSpan("CyclicThread::Sleep", "cactusrt", tracer_config.trace_sleep);
+      auto span = Tracer().WithSpan("Sleep", "cactusrt", tracer_config.trace_sleep);
       // TODO: maybe track busy wait latency? That feature is not even enabled.
       this->Config().scheduler->Sleep(next_wakeup_time_);
     }