diff --git a/CHANGELOG.md b/CHANGELOG.md index d88149e..127ee86 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/firmware/components/display/panel_esp.cpp b/firmware/components/display/panel_esp.cpp index 95ce448..cacac2f 100644 --- a/firmware/components/display/panel_esp.cpp +++ b/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(draw_cost_count), + static_cast(window_us / 1000), + static_cast(draw_cost_redraws), + static_cast(static_cast(draw_cost_redraws) * + kDrawCostReportPeriodUs / window_us), + static_cast(draw_cost_total_us / + static_cast(draw_cost_count)), + static_cast(draw_cost_worst_us), + static_cast(kServicePeriodUs), + static_cast(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) { diff --git a/firmware/components/ui/include/track_timer/ui/imu_meter.hpp b/firmware/components/ui/include/track_timer/ui/imu_meter.hpp index 7f48b98..6c32526 100644 --- a/firmware/components/ui/include/track_timer/ui/imu_meter.hpp +++ b/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(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 diff --git a/firmware/main/screen_router.cpp b/firmware/main/screen_router.cpp index 9bd7137..3c44414 100644 --- a/firmware/main/screen_router.cpp +++ b/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(radar_render_count_), + static_cast(ui::kImuTrailCapacity), + static_cast(radar_render_total_us_ / + static_cast(radar_render_count_)), + static_cast(radar_render_worst_us_), + static_cast(kDisplayServicePeriodUs), + static_cast(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_{}; diff --git a/tests/cpp/test_imu_meter.cpp b/tests/cpp/test_imu_meter.cpp index 756cb0d..560eba2 100644 --- a/tests/cpp/test_imu_meter.cpp +++ b/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(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(kOverfill - 1) / 100.0F)); input = sample(0.1F, 0.2F, 80); snapshot = meter.update(input, true);