diff --git a/lib/connector/meshcore_connector.dart b/lib/connector/meshcore_connector.dart index 04cbbbf..fdcfc98 100644 --- a/lib/connector/meshcore_connector.dart +++ b/lib/connector/meshcore_connector.dart @@ -703,11 +703,31 @@ class MeshCoreConnector extends ChangeNotifier { notifyListeners(); } + /// Aggregate cost of the per-contact conversation load, which runs once per + /// contact during a pull. It is fired unawaited from the contact handler, so + /// it escapes the frame-handler timing and has to be measured here. + int _convLoadCount = 0; + int _convLoadStoreMs = 0; + int _convLoadMergeMs = 0; + Future _loadMessagesForContact(String contactKeyHex) async { if (_loadedConversationKeys.contains(contactKeyHex)) return; _loadedConversationKeys.add(contactKeyHex); + final storeWatch = Stopwatch()..start(); final allMessages = await _messageStore.loadMessages(contactKeyHex); + storeWatch.stop(); + final mergeWatch = Stopwatch()..start(); + _convLoadCount++; + _convLoadStoreMs += storeWatch.elapsedMilliseconds; + if (_convLoadCount % 25 == 0) { + appLogger.info( + 'conversation loads: $_convLoadCount contacts, ' + 'store=${_convLoadStoreMs}ms(WALL, spans await - includes event-loop ' + 'queueing, NOT pure work) merge=${_convLoadMergeMs}ms(sync work)', + tag: 'Perf', + ); + } if (allMessages.isNotEmpty) { // Keep only the most recent N messages in memory to bound memory usage final windowedMessages = allMessages.length > _messageWindowSize @@ -748,6 +768,8 @@ class MeshCoreConnector extends ChangeNotifier { _conversations[contactKeyHex] = windowedMergedMessages; notifyListeners(); } + mergeWatch.stop(); + _convLoadMergeMs += mergeWatch.elapsedMilliseconds; } String _messageMergeKey(Message message) { @@ -1191,10 +1213,17 @@ class MeshCoreConnector extends ChangeNotifier { _contacts ..clear() ..addAll(cached); - for (final contact in cached) { - _ensureContactSmazSettingLoaded(contact.publicKeyHex); - _ensureContactCyr2LatSettingLoaded(contact.publicKeyHex); - } + // Load every contact's settings without notifying per contact, then + // notify once. Per-contact notification rebuilt the whole tree 2x per + // contact (600 rebuilds for 300 contacts), and each rebuild walks the + // contact list, which is what stalled the UI for ~44s on connect. + await Future.wait([ + for (final contact in cached) ...[ + _ensureContactSmazSettingLoaded(contact.publicKeyHex, notify: false), + _ensureContactCyr2LatSettingLoaded(contact.publicKeyHex, notify: false), + ], + ]); + notifyListeners(); } Future _loadDiscoveredContactCache() async { @@ -4342,7 +4371,64 @@ 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); + + /// 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 _frameCodeMicros = {}; + final Map _frameCodeCount = {}; + int _frameTotalMicros = 0; + void _handleFrame(List data) { + final handlerWatch = Stopwatch()..start(); + _handleFrameInner(data); + handlerWatch.stop(); + 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=$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 data) { if (data.isEmpty) return; _lastRxTime = DateTime.now(); @@ -4642,16 +4728,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(); - loadCachedChannels(); - - // Load persisted channel messages - 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(); @@ -4662,6 +4742,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 @@ -5001,6 +5101,28 @@ class MeshCoreConnector extends ChangeNotifier { return physicsMax; } + /// Coalesces notifications during a bulk contact pull. + /// + /// Outside a pull this notifies immediately, preserving live-update + /// behaviour for adverts arriving one at a time. + DateTime? _lastContactPullNotify; + static const Duration _contactPullNotifyInterval = Duration( + milliseconds: 250, + ); + + void _notifyContactPullThrottled() { + if (!_isLoadingContacts) { + notifyListeners(); + return; + } + final now = DateTime.now(); + final last = _lastContactPullNotify; + if (last == null || now.difference(last) >= _contactPullNotifyInterval) { + _lastContactPullNotify = now; + notifyListeners(); + } + } + void _handleContact(Uint8List frame, {bool isContact = true}) { final contactTmp = Contact.fromFrame(frame); if (contactTmp != null) { @@ -5088,7 +5210,14 @@ class MeshCoreConnector extends ChangeNotifier { _pathHistoryService!.handlePathUpdated(contact); } - notifyListeners(); + // During a bulk pull this fired once per contact, and each notification + // is a synchronous full-tree rebuild that itself walks the contact list. + // Measured at ~19ms per contact, which never tripped a per-call slow + // threshold but dominated total isolate time. The channel handler + // already guards its notify with _isLoadingChannels; this is the same + // guard, throttled rather than suppressed so the sync progress bar still + // advances while the pull runs. + _notifyContactPullThrottled(); // Show notification for new contact (advertisement) if (isNewContact && _appSettingsService != null) { @@ -5621,22 +5750,32 @@ class MeshCoreConnector extends ChangeNotifier { return frame.sublist(prefixOffset, prefixOffset + prefixLen); } - void _ensureContactSmazSettingLoaded(String contactKeyHex) { + /// [notify] is false for bulk loads, which notify once at the end instead. + /// Notifying per contact rebuilds the whole tree once per contact, and each + /// rebuild itself walks the contact list, so a large address book turns this + /// into O(contacts^2) work on the UI isolate. + Future _ensureContactSmazSettingLoaded( + String contactKeyHex, { + bool notify = true, + }) async { if (_contactSmazEnabled.containsKey(contactKeyHex)) return; - _contactSettingsStore.loadSmazEnabled(contactKeyHex).then((enabled) { - if (_contactSmazEnabled[contactKeyHex] == enabled) return; - _contactSmazEnabled[contactKeyHex] = enabled; - notifyListeners(); - }); + final enabled = await _contactSettingsStore.loadSmazEnabled(contactKeyHex); + if (_contactSmazEnabled[contactKeyHex] == enabled) return; + _contactSmazEnabled[contactKeyHex] = enabled; + if (notify) notifyListeners(); } - void _ensureContactCyr2LatSettingLoaded(String contactKeyHex) { + Future _ensureContactCyr2LatSettingLoaded( + String contactKeyHex, { + bool notify = true, + }) async { if (_contactCyr2LatEnabled.containsKey(contactKeyHex)) return; - _contactSettingsStore.loadCyr2LatEnabled(contactKeyHex).then((enabled) { - if (_contactCyr2LatEnabled[contactKeyHex] == enabled) return; - _contactCyr2LatEnabled[contactKeyHex] = enabled; - notifyListeners(); - }); + final enabled = await _contactSettingsStore.loadCyr2LatEnabled( + contactKeyHex, + ); + if (_contactCyr2LatEnabled[contactKeyHex] == enabled) return; + _contactCyr2LatEnabled[contactKeyHex] = enabled; + if (notify) notifyListeners(); } void _ensureContactCyr2LatProfileLoaded(String contactKeyHex) { diff --git a/lib/storage/channel_message_store.dart b/lib/storage/channel_message_store.dart index dfef8c3..63dc24a 100644 --- a/lib/storage/channel_message_store.dart +++ b/lib/storage/channel_message_store.dart @@ -32,11 +32,25 @@ class ChannelMessageStore { String _indexKey(int channelIndex) => '$keyFor$channelIndex'; /// Active storage key: PSK identity when known, else the slot index. + /// + /// The index fallback is legitimate before a channel list has loaded, but it + /// reads a DIFFERENT key: if history was already migrated to the PSK key, the + /// caller gets an empty list that is indistinguishable from data loss. + /// SAFELANE 6 - this must never be silent. Falling back where a resolver + /// exists means the channel list was not ready, which is the #333 race. String _storageKey(int channelIndex) { final pskHex = channelPskResolver?.call(channelIndex); if (pskHex != null && pskHex.isNotEmpty) { return '$keyFor$_pskMarker$pskHex'; } + if (channelPskResolver != null) { + appLogger.warn( + 'Channel $channelIndex has no PSK yet; falling back to the slot-index ' + 'key. Any history already migrated to the PSK key will read as EMPTY. ' + 'This means the channel list was not loaded first (#333).', + tag: 'Storage', + ); + } return _indexKey(channelIndex); } diff --git a/lib/storage/channel_order_store.dart b/lib/storage/channel_order_store.dart index 88d3f7a..4e268b2 100644 --- a/lib/storage/channel_order_store.dart +++ b/lib/storage/channel_order_store.dart @@ -29,13 +29,15 @@ class ChannelOrderStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating channel order from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } diff --git a/lib/storage/channel_settings_store.dart b/lib/storage/channel_settings_store.dart index e0b390f..e6af56b 100644 --- a/lib/storage/channel_settings_store.dart +++ b/lib/storage/channel_settings_store.dart @@ -25,13 +25,18 @@ class ChannelSettingsStore { bool? enabled = prefs.getBool(key); if (enabled == null) { // Attempt migration from legacy unscoped key on first load + // Only touch storage when a legacy key actually exists. This ran + // unconditionally, and on Windows shared_preferences re-serialises and + // rewrites the WHOLE prefs file on every mutation, so removing a key + // that was never there still cost a full multi-MB write. Repeated per + // channel/contact on connect, that blocked the UI isolate for ~38s. enabled = prefs.getBool(oldKey); - prefs.remove(oldKey); if (enabled != null) { appLogger.info( 'Migrating channel settings from legacy key $oldKey to scoped key $key', ); await prefs.setBool(key, enabled); + await prefs.remove(oldKey); } } return enabled ?? false; diff --git a/lib/storage/channel_store.dart b/lib/storage/channel_store.dart index 4f40482..596d3bc 100644 --- a/lib/storage/channel_store.dart +++ b/lib/storage/channel_store.dart @@ -22,13 +22,15 @@ class ChannelStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating channel messages from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } @@ -45,7 +47,11 @@ class ChannelStore { return jsonList .map((entry) => _fromJson(entry as Map)) .toList(); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error('Failed to decode channels: $e', tag: 'Storage'); return []; } } diff --git a/lib/storage/community_store.dart b/lib/storage/community_store.dart index c69d0b8..732ff47 100644 --- a/lib/storage/community_store.dart +++ b/lib/storage/community_store.dart @@ -28,13 +28,15 @@ class CommunityStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating communities from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } @@ -105,7 +107,11 @@ class CommunityStore { final communities = await loadCommunities(); try { return communities.firstWhere((c) => c.id == communityId); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error('Failed to decode communities: $e', tag: 'Storage'); return null; } } @@ -116,7 +122,11 @@ class CommunityStore { final communities = await loadCommunities(); try { return communities.firstWhere((c) => c.communityId == cid); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error('Failed to decode communities: $e', tag: 'Storage'); return null; } } diff --git a/lib/storage/contact_discovery_store.dart b/lib/storage/contact_discovery_store.dart index 3f6f171..796652e 100644 --- a/lib/storage/contact_discovery_store.dart +++ b/lib/storage/contact_discovery_store.dart @@ -3,6 +3,7 @@ import 'dart:typed_data'; import '../models/contact.dart'; import 'prefs_manager.dart'; +import '../utils/app_logger.dart'; class ContactDiscoveryStore { static const String _keyPrefix = 'discovered_contacts'; @@ -17,7 +18,14 @@ class ContactDiscoveryStore { return jsonList .map((entry) => _fromJson(entry as Map)) .toList(); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error( + 'Failed to decode discovered contacts: $e', + tag: 'Storage', + ); return []; } } diff --git a/lib/storage/contact_group_store.dart b/lib/storage/contact_group_store.dart index ce6a0c6..0813274 100644 --- a/lib/storage/contact_group_store.dart +++ b/lib/storage/contact_group_store.dart @@ -21,13 +21,15 @@ class ContactGroupStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating channel messages from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } diff --git a/lib/storage/contact_settings_store.dart b/lib/storage/contact_settings_store.dart index 682f1af..109f5eb 100644 --- a/lib/storage/contact_settings_store.dart +++ b/lib/storage/contact_settings_store.dart @@ -25,13 +25,18 @@ class ContactSettingsStore { bool? enabled = prefs.getBool(key); if (enabled == null) { // Attempt migration from legacy unscoped key on first load + // Only touch storage when a legacy key actually exists. This ran + // unconditionally, and on Windows shared_preferences re-serialises and + // rewrites the WHOLE prefs file on every mutation, so removing a key + // that was never there still cost a full multi-MB write. Repeated per + // channel/contact on connect, that blocked the UI isolate for ~38s. enabled = prefs.getBool(oldKey); - prefs.remove(oldKey); if (enabled != null) { appLogger.info( 'Migrating contact settings from legacy key $oldKey to scoped key $key', ); await prefs.setBool(key, enabled); + await prefs.remove(oldKey); } } return prefs.getBool(key) ?? false; diff --git a/lib/storage/contact_store.dart b/lib/storage/contact_store.dart index 5d1805d..9149046 100644 --- a/lib/storage/contact_store.dart +++ b/lib/storage/contact_store.dart @@ -23,13 +23,15 @@ class ContactStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating contacts from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } @@ -45,7 +47,11 @@ class ContactStore { return jsonList .map((entry) => _fromJson(entry as Map)) .toList(); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error('Failed to decode contacts: $e', tag: 'Storage'); return []; } } diff --git a/lib/storage/message_store.dart b/lib/storage/message_store.dart index ccaf9ea..96595e4 100644 --- a/lib/storage/message_store.dart +++ b/lib/storage/message_store.dart @@ -40,13 +40,18 @@ class MessageStore { String? jsonString = prefs.getString(key); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only touch storage when a legacy key actually exists. This ran + // unconditionally, and loadMessages is called once per contact during a + // contact pull. On Windows shared_preferences rewrites the WHOLE prefs + // file on every mutation, so each no-op remove cost a full multi-MB + // write - hundreds of them back to back on a large address book. final legacyJsonString = prefs.getString(oldKey); - prefs.remove(oldKey); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating messages from legacy key $oldKey to scoped key $key', ); await prefs.setString(key, legacyJsonString); + await prefs.remove(oldKey); jsonString = legacyJsonString; } } @@ -61,6 +66,13 @@ class MessageStore { final jsonList = jsonDecode(jsonString) as List; return jsonList.map((json) => _messageFromJson(json)).toList(); } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error( + 'Failed to decode messages for $contactKeyHex: $e', + tag: 'Storage', + ); return []; } } diff --git a/lib/storage/unread_store.dart b/lib/storage/unread_store.dart index 3b615b1..a9cd4df 100644 --- a/lib/storage/unread_store.dart +++ b/lib/storage/unread_store.dart @@ -35,13 +35,15 @@ class UnreadStore { String? jsonString = prefs.getString(keyFor); if (jsonString == null || jsonString.isEmpty) { // Attempt migration from legacy unscoped key on first load + // Only remove the legacy key when it actually exists: every prefs + // mutation rewrites the whole file on Windows. final legacyJsonString = prefs.getString(_keyPrefix); - prefs.remove(_keyPrefix); if (legacyJsonString != null && legacyJsonString.isNotEmpty) { appLogger.info( 'Migrating channel messages from legacy key $_keyPrefix to scoped key $keyFor', ); await prefs.setString(keyFor, legacyJsonString); + await prefs.remove(_keyPrefix); jsonString = legacyJsonString; } } @@ -55,7 +57,11 @@ class UnreadStore { try { final json = jsonDecode(jsonString) as Map; return json.map((key, value) => MapEntry(key, value as int)); - } catch (_) { + } catch (e) { + // SAFELANE 6: never swallow. A decode failure here is + // indistinguishable from 'no data' to the caller, which reads + // to the user as data loss. + appLogger.error('Failed to decode unread state: $e', tag: 'Storage'); return {}; } }