From 77625db575a2724aa6e79f03ca4887d578c7fae5 Mon Sep 17 00:00:00 2001
From: Strycher <strycher@gmail.com>
Date: Mon, 20 Jul 2026 13:31:04 -0400
Subject: [PATCH] perf(#306): measure cumulative sync time per frame code

The conversation-load metric was misread, and nearly caused a fix to the wrong
thing. It reported store=30138ms across 300 contacts, which looked like
loadMessages costing ~100ms each. It is not:

- The device-wide fallback key `messages_<dev>` does not exist on the
  reporting machine, and only 11 per-contact message keys exist in total, so
  loadMessages does three in-memory map lookups and returns empty.
- storeWatch spans an `await`, so it measures WALL time including event-loop
  queueing, not work. merge, which is synchronous and has no await, measures
  0ms - consistent with the isolate being busy elsewhere while those awaits
  wait their turn.

So the 30s is ~300 awaits each waiting for a busy isolate, not 30s of storage
work. The metric label now says so, rather than inviting the same misreading.

The per-call 100ms threshold cannot see the actual shape here: a handler that
takes 40ms and runs 234 times owns ~9s of isolate time and never trips it.
Frame handlers now accumulate synchronous time per frame code and report the
top codes by total, which names the owner regardless of per-call cost.

Diagnostics only, no behaviour change.

flutter analyze clean, dart format clean, 494 tests pass.
---
 lib/connector/meshcore_connector.dart | 45 +++++++++++++++++++++++++--
 1 file changed, 42 insertions(+), 3 deletions(-)

diff --git a/lib/connector/meshcore_connector.dart b/lib/connector/meshcore_connector.dart
index 2bfb1ca..af5b8a3 100644
--- a/lib/connector/meshcore_connector.dart
+++ b/lib/connector/meshcore_connector.dart
@@ -723,7 +723,8 @@ class MeshCoreConnector extends ChangeNotifier {
     if (_convLoadCount % 25 == 0) {
       appLogger.info(
         'conversation loads: $_convLoadCount contacts, '
-        'store=${_convLoadStoreMs}ms merge=${_convLoadMergeMs}ms cumulative',
+        'store=${_convLoadStoreMs}ms(WALL, spans await - includes event-loop '
+        'queueing, NOT pure work) merge=${_convLoadMergeMs}ms(sync work)',
         tag: 'Perf',
       );
     }
@@ -4376,17 +4377,55 @@ class MeshCoreConnector extends ChangeNotifier {
   /// once. Logged rather than assumed, so the offending code is named.
   static const Duration _slowHandlerThreshold = Duration(milliseconds: 100);
 
+  /// Cumulative synchronous time per frame code. A single handler under the
+  /// slow threshold can still dominate if it runs hundreds of times, which a
+  /// per-call threshold cannot see.
+  final Map<int, int> _frameCodeMicros = {};
+  final Map<int, int> _frameCodeCount = {};
+  int _frameTotalMicros = 0;
+
   void _handleFrame(List<int> data) {
     final handlerWatch = Stopwatch()..start();
     _handleFrameInner(data);
     handlerWatch.stop();
-    if (handlerWatch.elapsed > _slowHandlerThreshold && data.isNotEmpty) {
+    if (data.isEmpty) return;
+
+    final code = data[0];
+    final micros = handlerWatch.elapsedMicroseconds;
+    _frameCodeMicros[code] = (_frameCodeMicros[code] ?? 0) + micros;
+    _frameCodeCount[code] = (_frameCodeCount[code] ?? 0) + 1;
+    _frameTotalMicros += micros;
+
+    if (handlerWatch.elapsed > _slowHandlerThreshold) {
       appLogger.info(
-        'slow frame handler: code=${data[0]} blocked UI for '
+        'slow frame handler: code=$code blocked UI for '
         '${handlerWatch.elapsedMilliseconds}ms',
         tag: 'Perf',
       );
     }
+
+    // Periodic cumulative report: names the code that owns the most isolate
+    // time even when no single call is slow.
+    if (_frameTotalMicros > 2000000) {
+      final ranked = _frameCodeMicros.entries.toList()
+        ..sort((a, b) => b.value.compareTo(a.value));
+      final top = ranked
+          .take(4)
+          .map(
+            (e) =>
+                'code=${e.key} ${(e.value / 1000).round()}ms'
+                '/${_frameCodeCount[e.key]}calls',
+          )
+          .join('  ');
+      appLogger.info(
+        'frame handler cumulative (${(_frameTotalMicros / 1000).round()}ms '
+        'total sync): $top',
+        tag: 'Perf',
+      );
+      _frameTotalMicros = 0;
+      _frameCodeMicros.clear();
+      _frameCodeCount.clear();
+    }
   }
 
   void _handleFrameInner(List<int> data) {