feat(ui): give the G radar a three-second trace, and measure what drawing it costs

CHANGELOG.md

@@ -246,6 +246,32 @@ The project follows Semantic Versioning once the first firmware release is tagge
 
 ### Changed
 
+- the G radar's trace now covers **three seconds instead of 1.2**, and its length is
+  derived from the display cadence rather than stated as a bare count. `kImuTrailCapacity`
+  was `24`, which reads like a few seconds and was not: the trail is appended once per
+  display service, so at 20 Hz it held 1.2 s. The span is now what gets chosen
+  (`kImuTrailSpanMs = 3'000`, picked because a corner in a Seven runs two to four seconds,
+  so the driver sees the corner they just took) and the capacity follows from it. A
+  `static_assert` ties the assumed cadence to the real `kDisplayServicePeriodUs`, so
+  changing the display period fails the build instead of silently rescaling the trace
+- **render cost is measured rather than assumed**, which is what let the change above be
+  made safely. Two periodic log lines: `radar:` times the object work at the call site,
+  and `draw:` times `lv_timer_handler` in the panel task, which is where drawing actually
+  happens - repositioning an object only marks an area dirty. Measured on hardware:
+
+  | | 24 points | 60 points |
+  |---|---|---|
+  | object work, mean | 1,727 us | 2,395 us |
+  | share of the 50 ms display period | 3% | 4% |
+  | worst repaint | 23,597-23,813 us | 24,255-24,287 us |
+
+  Tripling the trace cost **2.3% more repaint time**, because 24 dots already spanned the
+  whole radar and the invalidated area was already saturated. Per-point object cost works
+  out at 18.6 us against a fixed 1.28 ms for the rings, labels and markers, so the dots
+  were never the expensive part. Without the measurement the obvious reading - 150% more
+  objects, so expect 150% more work - would have argued against a change that is nearly
+  free
+
 - the receiver now runs at **25 Hz**. Measured on hardware: 24.9 Hz observed, 57 frames,
   57 accepted, nothing rejected, no checksum errors, and 40 ms read back from the
   receiver's flash layer. The part was never in doubt - it was separately measured at

firmware/components/display/panel_esp.cpp

@@ -6,6 +6,7 @@
 #include "esp_lcd_panel_vendor.h"
 #include "esp_lcd_sh8601.h"
 #include "driver/gpio.h"
+#include "esp_log.h"
 #include "esp_timer.h"
 #include "freertos/FreeRTOS.h"
 #include "freertos/semphr.h"
@@ -124,6 +125,64 @@ void round_invalidated_area(lv_event_t* event) noexcept
 
 void tick(void*) noexcept { lv_tick_inc(kLvglTickPeriodMs); }
 
+// Windowed by time rather than by call count. The handler is called at the minimum delay
+// whether or not there is anything to draw, so a count-based window reports every few
+// tens of milliseconds and buries the log, while saying nothing about how often a real
+// redraw happens.
+constexpr std::int64_t kDrawCostReportPeriodUs = 10'000'000;
+// Above this, a handler call did real drawing rather than finding nothing dirty. The
+// separation is stark in practice - no-op calls are single-digit microseconds and a
+// redraw is thousands - so the exact threshold does not matter much.
+constexpr std::int64_t kDrawCostRedrawThresholdUs = 5'000;
+std::uint32_t draw_cost_count = 0;
+std::uint32_t draw_cost_redraws = 0;
+std::int64_t draw_cost_total_us = 0;
+std::int64_t draw_cost_worst_us = 0;
+std::int64_t draw_cost_window_started_us = 0;
+
+void record_draw_cost(const std::int64_t elapsed_us) noexcept
+{
+    draw_cost_count += 1;
+    draw_cost_total_us += elapsed_us;
+    if (elapsed_us > draw_cost_worst_us) {
+        draw_cost_worst_us = elapsed_us;
+    }
+    if (elapsed_us >= kDrawCostRedrawThresholdUs) {
+        draw_cost_redraws += 1;
+    }
+    const auto now_us = esp_timer_get_time();
+    if (draw_cost_window_started_us == 0) {
+        draw_cost_window_started_us = now_us;
+        return;
+    }
+    const auto window_us = now_us - draw_cost_window_started_us;
+    if (window_us < kDrawCostReportPeriodUs) {
+        return;
+    }
+    // The worst call is measured against the service period rather than reported alone,
+    // because this task also dispatches the UI service: drawing that overruns the period
+    // delays everything else on this task, and starving it is the failure #133 and #141
+    // were.
+    ESP_LOGI("track_timer",
+             "draw: %u calls in %lld ms, %u redraws (%lld per 10 s), mean %lld us, "
+             "worst %lld us (%lld us service period, worst %u%%)",
+             static_cast<unsigned>(draw_cost_count),
+             static_cast<long long>(window_us / 1000),
+             static_cast<unsigned>(draw_cost_redraws),
+             static_cast<long long>(static_cast<std::int64_t>(draw_cost_redraws) *
+                                    kDrawCostReportPeriodUs / window_us),
+             static_cast<long long>(draw_cost_total_us /
+                                    static_cast<std::int64_t>(draw_cost_count)),
+             static_cast<long long>(draw_cost_worst_us),
+             static_cast<long long>(kServicePeriodUs),
+             static_cast<unsigned>(draw_cost_worst_us * 100 / kServicePeriodUs));
+    draw_cost_count = 0;
+    draw_cost_redraws = 0;
+    draw_cost_total_us = 0;
+    draw_cost_worst_us = 0;
+    draw_cost_window_started_us = now_us;
+}
+
 void lvgl_task(void*) noexcept
 {
     auto delay_ms = kLvglMinDelayMs;
@@ -139,7 +198,14 @@ void lvgl_task(void*) noexcept
                     service_callback();
                 }
             }
+            // What #136 asked for a measurement of. lv_timer_handler is where the
+            // drawing actually happens - repositioning an object only marks an area
+            // dirty - so the cost of a trace redrawn through a 96,000-byte stripe buffer
+            // shows up here and nowhere else. Reported as a periodic summary, so whatever
+            // screen the device is sitting on is the screen being measured.
+            const auto draw_started_us = esp_timer_get_time();
             delay_ms = lv_timer_handler();
+            record_draw_cost(esp_timer_get_time() - draw_started_us);
             unlock();
         }
         if (delay_ms > kLvglMaxDelayMs) {

firmware/components/ui/include/track_timer/ui/imu_meter.hpp

@@ -13,7 +13,20 @@ namespace track_timer::ui {
 // gyroscope latched tilt as acceleration and had left and right swapped, so they are wrong
 // rather than merely old and are not migrated.
 inline constexpr std::uint32_t kImuMeterSchemaVersion = 2;
-inline constexpr std::size_t kImuTrailCapacity = 24;
+// The trail is appended once per display service, so a capacity on its own says nothing
+// about how much of a drive the trace shows: 24 points is two and a half seconds at 10 Hz
+// and a fifth of a second at 120 Hz. The span is therefore the figure that gets chosen and
+// the capacity is derived from it, with screen_router static_asserting that the cadence it
+// dispatches at is the one assumed here.
+inline constexpr std::int64_t kImuTrailSamplePeriodUs = 50'000;
+// Three seconds. Chosen against what the trace is for rather than as a round number: a
+// corner in a Seven runs roughly two to four seconds from turn-in to unwinding, so three
+// seconds shows the driver the corner they have just taken. The previous 24 points were
+// 1.2 s at this cadence, which showed them the middle of it.
+inline constexpr std::int64_t kImuTrailSpanMs = 3'000;
+inline constexpr std::size_t kImuTrailCapacity =
+    static_cast<std::size_t>(kImuTrailSpanMs * 1'000 / kImuTrailSamplePeriodUs);
+static_assert(kImuTrailCapacity > 1, "a trace needs more than one point");
 inline constexpr float kStandardGravityMps2 = 9.80665F;
 // What the radar can draw. A dot has to stay on the display, so the drawn value is held
 // inside this - but a recorded peak is a different quantity with a different purpose, and

firmware/main/screen_router.cpp

@@ -886,6 +886,42 @@ class ScreenRouter {
         }
     }
 
+    // Render cost, which #136 asked for a measurement of rather than an assumption
+    // about. The trace is the most demanding drawing this device does: every trail point
+    // is an LVGL object that is repositioned and restyled on each update, so raising
+    // kImuTrailCapacity raises the work here one-for-one.
+    //
+    // Timed at the call site rather than inside GRadarScreen so the UI component stays
+    // free of esp_timer and remains buildable on the host, and reported as a periodic
+    // summary so the figure can be read off an ordinary boot log instead of needing a
+    // profiler attached.
+    void record_radar_render(const std::int64_t elapsed_us) noexcept
+    {
+        radar_render_count_ += 1;
+        radar_render_total_us_ += elapsed_us;
+        radar_render_worst_us_ = std::max(radar_render_worst_us_, elapsed_us);
+        if (radar_render_count_ < kRadarRenderReportInterval) {
+            return;
+        }
+        // Against the budget, because the absolute figure means little on its own: this
+        // work has to finish inside the display period it is dispatched from, or the
+        // cadence that every other screen shares is what gives way.
+        ESP_LOGI("track_timer",
+                 "radar: %u renders of %u trail points, mean %lld us, worst %lld us "
+                 "(%lld us budget, worst %u%%)",
+                 static_cast<unsigned>(radar_render_count_),
+                 static_cast<unsigned>(ui::kImuTrailCapacity),
+                 static_cast<long long>(radar_render_total_us_ /
+                                        static_cast<std::int64_t>(radar_render_count_)),
+                 static_cast<long long>(radar_render_worst_us_),
+                 static_cast<long long>(kDisplayServicePeriodUs),
+                 static_cast<unsigned>(radar_render_worst_us_ * 100 /
+                                       kDisplayServicePeriodUs));
+        radar_render_count_ = 0;
+        radar_render_total_us_ = 0;
+        radar_render_worst_us_ = 0;
+    }
+
     void service_imu() noexcept
     {
         board::ImuSample sample{};
@@ -943,7 +979,9 @@ class ScreenRouter {
         // and it invalidates areas nobody is looking at.
         if (radar_ != nullptr && radar_root_ != nullptr &&
             lv_screen_active() == radar_root_) {
+            const auto started_us = esp_timer_get_time();
             radar_->update(snapshot);
+            record_radar_render(esp_timer_get_time() - started_us);
         }
         // Same gate, same reason. The snapshot stays at its default until there is a
         // transport to fill it (#17, #18), which is why the screen has to render an absent
@@ -2418,6 +2456,19 @@ class ScreenRouter {
     ui::ClockState logged_clock_state_{ui::ClockState::no_receiver};
     // Everything that is not the GNSS poll runs at this period rather than the tick's.
     static constexpr std::int64_t kDisplayServicePeriodUs = 50'000;
+    // The trail's span in seconds is this period times its capacity, so the two cannot be
+    // reasoned about separately. Asserted rather than commented: changing the cadence
+    // silently rescales the trace, which is how it came to hold roughly a second while
+    // claiming to hold a few.
+    static_assert(kDisplayServicePeriodUs == ui::kImuTrailSamplePeriodUs,
+                  "the trail is appended once per display service, and its span is "
+                  "derived from that period");
+    // Ten seconds at the display cadence. Long enough to average over a real trace rather
+    // than a single frame, short enough that a boot capture contains several reports.
+    static constexpr std::uint32_t kRadarRenderReportInterval = 200;
+    std::uint32_t radar_render_count_{0};
+    std::int64_t radar_render_total_us_{0};
+    std::int64_t radar_render_worst_us_{0};
     std::int64_t last_display_service_us_{0};
     gnss::GnssTransport* gnss_transport_{nullptr};
     gnss::GnssPipeline gnss_pipeline_{};

tests/cpp/test_imu_meter.cpp

@@ -40,6 +40,16 @@ track_timer::ui::ImuMeterInput vertical_sample(const float vertical_g,
 
 }  // namespace
 
+// #136 asked for "a trace of the last few seconds". That is a property of the span, so the
+// span is what gets asserted: a capacity on its own could mean any duration, which is how
+// 24 points came to be read as a few seconds when it was one and a fifth of one.
+static_assert(track_timer::ui::kImuTrailSpanMs >= 2'000,
+              "the trace has to cover a corner rather than a fraction of one");
+static_assert(track_timer::ui::kImuTrailCapacity *
+                      track_timer::ui::kImuTrailSamplePeriodUs / 1'000 ==
+                  track_timer::ui::kImuTrailSpanMs,
+              "the capacity has to hold exactly the span it claims to");
+
 int main()
 {
     using namespace track_timer;
@@ -59,13 +69,20 @@ int main()
     assert(near(snapshot.peaks.braking_g, 1.1F));
     assert(near(snapshot.peaks.left_g, 0.9F));
 
-    for (std::uint64_t index = 0; index < 40; ++index) {
+    // Overfilled relative to whatever the capacity currently is, not to a literal: the
+    // capacity is derived from the trace span and the display cadence now, so a test
+    // written against the number it happens to produce breaks every time either changes
+    // and tells you nothing about the ring buffer either way. Sixteen past full is enough
+    // to prove the oldest points are dropped rather than the newest refused.
+    constexpr std::uint64_t kOverfill = ui::kImuTrailCapacity + 16;
+    for (std::uint64_t index = 0; index < kOverfill; ++index) {
         input = sample(static_cast<float>(index) / 100.0F, 0.1F, 30 + index);
         meter.update(input, false);
     }
     assert(meter.snapshot().trail_count == ui::kImuTrailCapacity);
     assert(meter.trail_point(ui::kImuTrailCapacity).lateral_g == 0.0F);
-    assert(near(meter.trail_point(ui::kImuTrailCapacity - 1).lateral_g, 0.39F));
+    assert(near(meter.trail_point(ui::kImuTrailCapacity - 1).lateral_g,
+                static_cast<float>(kOverfill - 1) / 100.0F));
 
     input = sample(0.1F, 0.2F, 80);
     snapshot = meter.update(input, true);