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.
integration/290-306-335
Strycher 1 day ago
parent 30ab360d66
commit 77625db575

@ -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) {

Loading…
Cancel
Save

Powered by TurnKey Linux.