From bd8779697a70c4ffec90cf3a3ca0668f5ba2fb97 Mon Sep 17 00:00:00 2001 From: Strycher Date: Mon, 20 Jul 2026 03:57:41 -0400 Subject: [PATCH] perf(#306): time startup loads and frame handlers to locate the UI stalls Two reported freezes: one shortly after connect, one during channel sync, with the sync progress bar never repainting and then completing all at once. That is the UI isolate being blocked, and the log already shows the signature - a long silence followed by many frames sharing one timestamp, which is queued input flushing after the loop frees up. The previous fix (batching 600 per-contact notifications) moved the stall from 43.6s to 40.1s, which is noise. It was the wrong culprit, so this replaces guessing with measurement: - The post-SELF_INFO cache load is split into named steps, each timed and logged as `startup-load took Nms`. The step order is unchanged, and cachedChannels still runs before channelMessages so PSK-keyed history resolves. - Every RX frame handler is timed, and any that occupies the isolate for more than 100ms logs `slow frame handler: code=N blocked UI for Nms`. This names the handler wherever it is, rather than requiring a guess about which one. No behaviour change. Diagnostics only, kept as Perf-tagged logging because this class of stall is worth catching again. flutter analyze clean, dart format clean, 469 tests pass. --- lib/connector/meshcore_connector.dart | 57 ++++++++++++++++++++------- 1 file changed, 43 insertions(+), 14 deletions(-) diff --git a/lib/connector/meshcore_connector.dart b/lib/connector/meshcore_connector.dart index d86443b..1d297c8 100644 --- a/lib/connector/meshcore_connector.dart +++ b/lib/connector/meshcore_connector.dart @@ -4349,7 +4349,26 @@ class MeshCoreConnector extends ChangeNotifier { } } + /// Any frame handler that occupies the UI isolate long enough to drop + /// frames is a bug: it stalls rendering, so progress bars freeze and input + /// stops responding while sync appears to do nothing and then finish at + /// once. Logged rather than assumed, so the offending code is named. + static const Duration _slowHandlerThreshold = Duration(milliseconds: 100); + void _handleFrame(List data) { + final handlerWatch = Stopwatch()..start(); + _handleFrameInner(data); + handlerWatch.stop(); + if (handlerWatch.elapsed > _slowHandlerThreshold && data.isNotEmpty) { + appLogger.info( + 'slow frame handler: code=${data[0]} blocked UI for ' + '${handlerWatch.elapsedMilliseconds}ms', + tag: 'Perf', + ); + } + } + + void _handleFrameInner(List data) { if (data.isEmpty) return; _lastRxTime = DateTime.now(); @@ -4649,20 +4668,10 @@ class MeshCoreConnector extends ChangeNotifier { _channelStore.setPublicKeyHex = selfPublicKeyHex; _unreadStore.setPublicKeyHex = selfPublicKeyHex; - // Now that we have self info, we can load all the persisted data for this node - _loadChannelOrder(); - loadContactCache(); - loadChannelSettings(); - - // Channel history is keyed by the channel's PSK (#194), and the resolver - // set above reads that PSK out of _channels. So the channel list MUST be - // loaded before the messages are: loading them concurrently leaves the - // resolver returning null, _storageKey() silently falls back to the legacy - // slot-index key, and every channel reads as empty even though its history - // is intact under the PSK key. - unawaited(loadCachedChannels().then((_) => loadAllChannelMessages())); - loadUnreadState(); - _loadDiscoveredContactCache(); + // Now that we have self info, we can load all the persisted data for this + // node. Each step is timed: this sequence has stalled the UI isolate for + // ~40s on a large store, and the timings say which step is responsible. + unawaited(_timedStartupLoad()); _awaitingSelfInfo = false; _selfInfoRetryTimer?.cancel(); @@ -4673,6 +4682,26 @@ class MeshCoreConnector extends ChangeNotifier { _maybeStartInitialChannelSync(); } + Future _timedStartupLoad() async { + Future step(String name, Future Function() body) async { + final sw = Stopwatch()..start(); + await body(); + sw.stop(); + appLogger.info( + 'startup-load $name took ${sw.elapsedMilliseconds}ms', + tag: 'Perf', + ); + } + + await step('channelOrder', () async => _loadChannelOrder()); + await step('contactCache', loadContactCache); + await step('channelSettings', () => loadChannelSettings()); + await step('cachedChannels', loadCachedChannels); + await step('channelMessages', () => loadAllChannelMessages()); + await step('unreadState', loadUnreadState); + await step('discoveredContacts', _loadDiscoveredContactCache); + } + /// Extract the additive `offband_caps` byte from a device-info reply. /// /// Offset verified against firmware MyMesh.cpp: the reply tail is three