ui: publish draw times + add test (#26119)

* ui: publish draw times + add test

* add some checks

* adjust

* fix linter

* update max

Co-authored-by: Comma Device <device@comma.ai>

cereal

@@ -1 +1 @@
-Subproject commit 5766e645f2ee2a131b145fb1ea9e3b7c55a4a740
+Subproject commit 107048c83ec2f488286a1be314e7aece0a20a6b1

selfdrive/debug/check_timings.py

@@ -19,7 +19,7 @@ if __name__ == "__main__":
       for m in msgs:
         ts[s].append(m.logMonoTime / 1e6)
 
-      if len(ts[s]):
+      if len(ts[s]) > 2:
         d = np.diff(ts[s])
         print(f"{s:25} {np.mean(d):.2f} {np.std(d):.2f} {np.max(d):.2f} {np.min(d):.2f}")
     time.sleep(1)

selfdrive/test/test_onroad.py

@@ -120,8 +120,8 @@ class TestOnroad(unittest.TestCase):
     if "DEBUG" in os.environ:
       segs = filter(lambda x: os.path.exists(os.path.join(x, "rlog")), Path(ROOT).iterdir())
       segs = sorted(segs, key=lambda x: x.stat().st_mtime)
-      print(segs[-1])
+      print(segs[-2])
-      cls.lr = list(LogReader(os.path.join(segs[-1], "rlog")))
+      cls.lr = list(LogReader(os.path.join(segs[-2], "rlog")))
       return
 
     # setup env
@@ -187,6 +187,25 @@ class TestOnroad(unittest.TestCase):
     big_logs = [f for f, n in cnt.most_common(3) if n / sum(cnt.values()) > 30.]
     self.assertEqual(len(big_logs), 0, f"Log spam: {big_logs}")
 
+  def test_ui_timings(self):
+    result = "\n"
+    result += "------------------------------------------------\n"
+    result += "-------------- UI Draw Timing ------------------\n"
+    result += "------------------------------------------------\n"
+
+    ts = [m.uiDebug.drawTimeMillis for m in self.lr if m.which() == 'uiDebug']
+    result += f"min  {min(ts):.2f}ms\n"
+    result += f"max  {max(ts):.2f}ms\n"
+    result += f"std  {np.std(ts):.2f}ms\n"
+    result += f"mean {np.mean(ts):.2f}ms\n"
+    result += "------------------------------------------------\n"
+    print(result)
+
+    self.assertGreater(len(ts), 20*50, "insufficient samples")
+    self.assertLess(max(ts), 30.)
+    self.assertLess(np.mean(ts), 10.)
+    self.assertLess(np.std(ts), 5.)
+
   def test_cpu_usage(self):
     proclogs = [m for m in self.lr if m.which() == 'procLog']
     self.assertGreater(len(proclogs), service_list['procLog'].frequency * 45, "insufficient samples")

selfdrive/ui/qt/onroad.cc

@@ -176,6 +176,8 @@ void OnroadAlerts::paintEvent(QPaintEvent *event) {
 // NvgWindow
 
 NvgWindow::NvgWindow(VisionStreamType type, QWidget* parent) : fps_filter(UI_FREQ, 3, 1. / UI_FREQ), CameraViewWidget("camerad", type, true, parent) {
+  pm = std::make_unique<PubMaster, const std::initializer_list<const char *>>({"uiDebug"});
+
   engage_img = loadPixmap("../assets/img_chffr_wheel.png", {img_size, img_size});
   dm_img = loadPixmap("../assets/img_driver_face.png", {img_size, img_size});
 }
@@ -542,6 +544,8 @@ void NvgWindow::drawLead(QPainter &painter, const cereal::ModelDataV2::LeadDataV
 }
 
 void NvgWindow::paintGL() {
+  const double start_draw_t = millis_since_boot();
+
   UIState *s = uiState();
   const cereal::ModelDataV2::Reader &model = (*s->sm)["modelV2"].getModelV2();
   CameraViewWidget::setFrameId(model.getFrameId());
@@ -575,6 +579,12 @@ void NvgWindow::paintGL() {
     LOGW("slow frame rate: %.2f fps", fps);
   }
   prev_draw_t = cur_draw_t;
+
+  // publish debug msg
+  MessageBuilder msg;
+  auto m = msg.initEvent().initUiDebug();
+  m.setDrawTimeMillis(cur_draw_t - start_draw_t);
+  pm->send("uiDebug", msg);
 }
 
 void NvgWindow::showEvent(QShowEvent *event) {

selfdrive/ui/qt/onroad.h

@@ -68,6 +68,7 @@ private:
   bool has_eu_speed_limit = false;
   bool v_ego_cluster_seen = false;
   int status = STATUS_DISENGAGED;
+  std::unique_ptr<PubMaster> pm;
 
 protected:
   void paintGL() override;