From cacf029754685a6cfd1fed1958ad3bcc0d1596d3 Mon Sep 17 00:00:00 2001 From: abdulsaheel Date: Wed, 29 Jul 2026 00:07:53 +0530 Subject: [PATCH 1/2] fix(crashlytics): close the four top 0.9.19/0.9.20 production issues MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Each of these was a real defect that a foreground assumption or an unbounded read made invisible until it hit a user's device. 1. IMPORT/EXPORT OOM. `importFromDb` ran `src.query(t)` per table and held the whole result live for the insert loop. sqflite materialises an entire result set as Java objects BEFORE any of it crosses the channel, so importing another device's `decoded_onehz` (86,400 rows per day) exhausted the 256 MB Dalvik heap — the production `java.lang.OutOfMemoryError` blamed on a BLE binder callback, which only ever surfaced there because that was the next thread to allocate. Both paths now page on rowid (keyset, not OFFSET, which would re-scan the prefix quadratically), one transaction per page. Each decoded_onehz row's orphan guard still rides in the SAME transaction as the row it guards — that invariant is per-row, not per-table — and every write stays INSERT OR REPLACE keyed on the row's own identity, so an interrupted import converges on re-run. 2. UNBOUNDED RR FALLBACK. `decodedRrByCounterRange`'s degraded branch (endpoint row pruned) treats its arguments as a bare counter span, and the strap's counter resets on reboot — a reboot-straddling page degenerated to `0 .. ~1200000`, i.e. the whole table, on the same heap. Capped, with `decodedRrFallbackTruncations` counting any short read so truncated HRV input can never pass as a complete one. 3. BACKGROUND DERIVE TIMEOUTS. `day_blocks_failed` ("timed out after 0:01:30") came only from `IosBgTask._run`. Three concurrent day-lanes win when there are spare cores; a throttled background slot has none, so the lanes divided one budget three ways and a wall-clock timeout turned "3 days derived" into "3 days timed out". Headless entries now take one lane and a 4-minute budget via a pure `DerivePacing`; serial lanes also cap peak memory at one day's substrate. 4. JANK FALSE POSITIVES. The watchdog gated on `FrameTiming.totalSpan`, which spans vsync-start to raster-end and therefore includes the gap across an app resume — producing "Slow frame: 16358ms (build=0 raster=8)", a 16-second stutter in which the engine did 8 ms of work. That single class became the top issue by impacted users and buried real signal. `JankPolicy` gates on build+raster, the cost the app actually controls and the only one a fix would move; totalSpan is still attached as context, with idle_ms, so a scheduling-delay pattern stays visible. Also fixes the ImportScreen double-tap crash: `_busy` only went true once an import was RUNNING, leaving the option cards live while the native sheet was still opening, so a second tap threw `PlatformException(already_active)` from an unawaited context. Guarded by a `_picking` flag plus a catch that refuses to let a picker failure be fatal. The three tuning/verdict decisions live in pure classes (DerivePacing, JankPolicy) so they are unit-testable without an isolate, a background slot, a SchedulerBinding or a Firebase app. 989 tests pass; analyze clean. No analytics output changed, so kAlgoVersion stays at 50. --- ios/ExportOptions/AppStoreConnect.plist | 18 ++ lib/compute/background_derivation.dart | 3 +- lib/compute/derivation_engine.dart | 30 ++- lib/compute/derive_pacing.dart | 56 +++++ lib/data/db.dart | 301 ++++++++++++++++-------- lib/sync/background_sync.dart | 1 + lib/sync/ios_bg_task.dart | 6 +- lib/telemetry/jank_policy.dart | 90 +++++++ lib/telemetry/telemetry_service.dart | 45 ++-- lib/ui/import/import_screen.dart | 58 ++++- test/db_paged_import_export_test.dart | 265 +++++++++++++++++++++ test/derive_pacing_test.dart | 66 ++++++ test/jank_policy_test.dart | 90 +++++++ 13 files changed, 889 insertions(+), 140 deletions(-) create mode 100644 ios/ExportOptions/AppStoreConnect.plist create mode 100644 lib/compute/derive_pacing.dart create mode 100644 lib/telemetry/jank_policy.dart create mode 100644 test/db_paged_import_export_test.dart create mode 100644 test/derive_pacing_test.dart create mode 100644 test/jank_policy_test.dart diff --git a/ios/ExportOptions/AppStoreConnect.plist b/ios/ExportOptions/AppStoreConnect.plist new file mode 100644 index 00000000..baa73cc9 --- /dev/null +++ b/ios/ExportOptions/AppStoreConnect.plist @@ -0,0 +1,18 @@ + + + + + method + app-store-connect + teamID + 2U62X3RF3R + signingStyle + automatic + destination + upload + uploadSymbols + + stripSwiftSymbols + + + diff --git a/lib/compute/background_derivation.dart b/lib/compute/background_derivation.dart index 2be80552..f3f3b3cd 100644 --- a/lib/compute/background_derivation.dart +++ b/lib/compute/background_derivation.dart @@ -66,7 +66,8 @@ void derivationDispatcher() { } else if (task == kHeavyDeriveTaskName) { debugPrint('[bg-derive] triggered by WorkManager'); final profile = await _loadProfile(); - final engine = DerivationEngine(log: (m) => debugPrint('[bg-derive] $m')); + final engine = DerivationEngine( + log: (m) => debugPrint('[bg-derive] $m'), background: true); await engine.run(profile, heavy: true); // Baseline-dirty rescan on the scheduled tick: refresh baseline-dependent // scalars on recent finalized days when the rolling baseline has moved. diff --git a/lib/compute/derivation_engine.dart b/lib/compute/derivation_engine.dart index f6acb464..0b274ce6 100644 --- a/lib/compute/derivation_engine.dart +++ b/lib/compute/derivation_engine.dart @@ -37,6 +37,7 @@ import '../notify/notification_event.dart'; import '../notify/tap_router.dart' show kRouteWorkoutSuggestion; import '../telemetry/telemetry_service.dart'; import 'crossday_pipeline.dart'; +import 'derive_pacing.dart'; import 'derive_prepare.dart'; import 'onehz_pipeline.dart'; import 'profile.dart'; @@ -655,9 +656,17 @@ Future runWithConcurrency( } class DerivationEngine { - DerivationEngine({this.log}); + DerivationEngine({this.log, this.background = false}); final void Function(String)? log; + /// True when this engine was constructed inside a headless/background entry + /// (iOS BGProcessingTask / BGAppRefreshTask, Android WorkManager, the + /// post-drain background sync pass). The OS throttles CPU hard in those + /// contexts, which changes two tuning decisions — see [_deriveConcurrency] + /// and [_perDayTimeout]. Set at construction, not per-run, so a long-lived + /// foreground engine can never inherit background tuning by accident. + final bool background; + bool _running = false; bool get running => _running; final Map _diag = { @@ -1493,9 +1502,13 @@ class DerivationEngine { 'v$kAlgoVersion|na'; } + /// Foreground vs background pacing — lane count and per-day wall-clock + /// budget. See [DerivePacing] for why the background numbers differ. + DerivePacing get _pacing => DerivePacing(background: background); + /// Max wall-clock for ONE day's off-isolate compute. On timeout the day is /// skipped so the sweep always makes progress. - static const Duration _perDayTimeout = Duration(seconds: 90); + Duration get _perDayTimeout => _pacing.perDayTimeout; /// Throttle for the readiness-absent diagnostic log — one per calendar day /// so repeated light-pass re-derives of today don't spam the outbox. @@ -1510,17 +1523,12 @@ class DerivationEngine { /// substrate loads + compute-isolate all finishing before the next day even /// started), which wastes every core beyond the one doing the current day's /// work. Running several days' isolate work genuinely concurrently gets - /// real wall-clock speedup from the device's other cores. Capped - /// conservatively — this is a phone doing background/foreground compute, - /// not a server batch job — rather than using every available core. - static const int _maxDeriveConcurrency = 3; - + /// real wall-clock speedup from the device's other cores — in the FOREGROUND. + /// A headless background slot has no spare cores to soak up, so it takes one + /// lane; [DerivePacing] owns that decision and explains it. int get _deriveConcurrency { try { - return math.max( - 1, - math.min(_maxDeriveConcurrency, Platform.numberOfProcessors), - ); + return _pacing.concurrency(Platform.numberOfProcessors); } catch (_) { return 1; // Platform unavailable on this target — sequential fallback } diff --git a/lib/compute/derive_pacing.dart b/lib/compute/derive_pacing.dart new file mode 100644 index 00000000..36d1f486 --- /dev/null +++ b/lib/compute/derive_pacing.dart @@ -0,0 +1,56 @@ +// derive_pacing.dart — how hard to push per-day derivation, and how long to +// wait for it, depending on whether we are in the foreground or in a headless +// OS-granted background slot. +// +// WHY THIS EXISTS (production, Crashlytics 0.9.20 / iOS 27): +// `_runDayBlocksCancellable` was reporting `day_blocks_failed` — +// "TimeoutException: day-blocks computation timed out after 0:01:30" — from +// inside `IosBgTask._run`, i.e. only ever in BACKGROUND. Two foreground +// assumptions were being applied to a context that breaks both: +// +// 1. CONCURRENCY. Running 3 day-lanes concurrently is a win when there are +// spare cores. A background task does not get spare cores — it gets a +// throttled slice of CPU. Three lanes therefore do not go faster; they +// divide one budget three ways and make each day ~3x slower in wall-clock. +// Paired with a wall-clock timeout, that converts "3 days derived" into +// "3 days timed out". Serial lanes also cap peak memory at one day's +// substrate instead of three. +// +// 2. TIMEOUT. The 90 s guard exists to survive a HUNG day, but it is measured +// in wall clock, and wall clock stops tracking work once the OS throttles +// us. A day that computes in 20 s foreground can legitimately need several +// times that in a BGProcessingTask on a busy or thermally-limited device. +// +// Kept pure and separate so the tuning is unit-testable without a database, an +// isolate, or a real background slot. + +/// Pacing decisions for one derivation run. +class DerivePacing { + const DerivePacing({required this.background}); + + /// True for headless entries: iOS BGProcessingTask / BGAppRefreshTask, + /// Android WorkManager, and the derive pass that follows a background drain. + final bool background; + + /// Upper bound on foreground day-lanes. Deliberately conservative — this is + /// a phone doing work alongside the UI, not a server batch job. + static const int maxForegroundConcurrency = 3; + + static const Duration foregroundPerDayTimeout = Duration(seconds: 90); + static const Duration backgroundPerDayTimeout = Duration(minutes: 4); + + /// Worker-pool size. [cores] is the device's processor count; pass whatever + /// `Platform.numberOfProcessors` reported (callers that cannot read it should + /// pass 1 and get the sequential fallback). + int concurrency(int cores) { + if (background) return 1; + if (cores < 1) return 1; + return cores < maxForegroundConcurrency ? cores : maxForegroundConcurrency; + } + + /// Max wall-clock for ONE day's off-isolate compute. On timeout the day is + /// skipped so the sweep always makes progress; the headline result still + /// persists (partial) and stays un-finalized for a later retry. + Duration get perDayTimeout => + background ? backgroundPerDayTimeout : foregroundPerDayTimeout; +} diff --git a/lib/data/db.dart b/lib/data/db.dart index cb528a42..f2f42d81 100644 --- a/lib/data/db.dart +++ b/lib/data/db.dart @@ -2580,6 +2580,12 @@ class LocalDb { ); } + /// How many times [decodedRrByCounterRange]'s degraded counter-span fallback + /// hit its row cap and therefore returned an INCOMPLETE set of beats. Any + /// value above zero means some window's HRV was computed from truncated + /// input; it should stay at zero in normal operation. + static int decodedRrFallbackTruncations = 0; + /// Sparse RR beats for one contiguous decoded 1 Hz page. /// /// [fromCounter] / [toCounter] are the page's FIRST and LAST row counters, as @@ -2625,13 +2631,33 @@ class LocalDb { } final lo = fromCounter <= toCounter ? fromCounter : toCounter; final hi = fromCounter <= toCounter ? toCounter : fromCounter; - return db.query( + // BOUNDED. This branch is reached when an endpoint row is not in + // `decoded_onehz` — a prune, or an import's REPLACE + orphan-guard DELETE + // landing between the frame-page read and this call. The caller's counters + // are then just a span, and because the strap's counter resets on reboot a + // reboot-straddling page degenerates to `0 .. ~1200000`, i.e. effectively + // the whole table. Unbounded, that is a hundreds-of-MB platform-heap read + // on the same Java heap that OOMed the import path. A page is 2000 frames + // and a second rarely carries more than a handful of beats, so this cap is + // orders of magnitude above any legitimate page — reaching it means the + // degraded path is being used for a range it was never meant to serve. + const fallbackBeatCap = 200000; + final rows = await db.query( 'decoded_rr', columns: ['counter', 'beat_index', 'rr_ts_ms', 'rr_ms'], where: 'counter >= ? AND counter <= ?', whereArgs: [lo, hi], orderBy: 'counter ASC, beat_index ASC', + limit: fallbackBeatCap, ); + // Never truncate silently — a short read here means missing beats, which + // shows up downstream as understated HRV rather than as an error. db.dart + // takes no telemetry dependency (it has to run inside compute isolates), so + // the fact is recorded as a counter the Diagnostics screen can surface. + if (rows.length >= fallbackBeatCap) { + decodedRrFallbackTruncations++; + } + return rows; } // ── VERSIONED DERIVED STORE I/O (day_result; main isolate only) ───────────── @@ -2977,72 +3003,100 @@ class LocalDb { }, ); - Future copyRows( + // Every source read on the export path is PAGED on rowid. A day-ranged + // `SELECT *` over `decoded_onehz` is 86,400 rows, and sqflite materialises + // a whole result set as Java objects before any of it reaches Dart — the + // same platform-heap exhaustion that OOMed the import path. Keyset, not + // OFFSET, so paging stays linear. + const exportPageSize = 2000; + const rowidKey = '_rowid'; + + /// Streams `table` (optionally filtered) into [out] one page at a time, + /// calling [onPage] with each page after it has been written. + Future copyPaged( String table, { String? where, List whereArgs = const [], + Future Function(List> page)? onPage, }) async { - final rows = await src.query(table, where: where, whereArgs: whereArgs); - if (rows.isEmpty) return; - await out.transaction((txn) async { - final batch = txn.batch(); - for (final row in rows) { - batch.insert( - table, - Map.from(row), - conflictAlgorithm: ConflictAlgorithm.replace, - ); - } - await batch.commit(noResult: true); - }); - } - - Future copyRawRange(int startSec, int endSec) async { - final decoded = await src.query( - 'decoded_onehz', - where: 'rec_ts >= ? AND rec_ts < ?', - whereArgs: [startSec, endSec], - ); - if (decoded.isNotEmpty) { + var lastRowid = 0; + while (true) { + final clause = where == null ? '' : 'AND ($where) '; + final page = await src.rawQuery( + 'SELECT rowid AS $rowidKey, * FROM $table ' + 'WHERE rowid > ? $clause' + 'ORDER BY rowid ASC LIMIT ?', + [lastRowid, ...whereArgs, exportPageSize], + ); + if (page.isEmpty) return; await out.transaction((txn) async { final batch = txn.batch(); - for (final row in decoded) { + for (final row in page) { + final clean = { + for (final e in row.entries) + if (e.key != rowidKey) e.key: e.value, + }; batch.insert( - 'decoded_onehz', - Map.from(row), + table, + clean, conflictAlgorithm: ConflictAlgorithm.replace, ); } await batch.commit(noResult: true); }); - final counters = [ - for (final row in decoded) - if (row['counter'] != null) row['counter'], - ]; - // CHUNKED `IN (…)`: a full day is 86 400 counters, two orders of - // magnitude past SQLITE_MAX_VARIABLE_NUMBER — one giant statement can - // never bind. (This never surfaced only because the missing `version:` - // above aborted the export earlier.) - for (final chunk in _sqlVarChunks(counters)) { - final placeholders = List.filled(chunk.length, '?').join(','); - final rr = await src.rawQuery( - 'SELECT * FROM decoded_rr WHERE counter IN ($placeholders)', - chunk, - ); - if (rr.isEmpty) continue; - await out.transaction((txn) async { - final batch = txn.batch(); - for (final row in rr) { - batch.insert( - 'decoded_rr', - Map.from(row), - conflictAlgorithm: ConflictAlgorithm.replace, - ); - } - await batch.commit(noResult: true); - }); - } + if (onPage != null) await onPage(page); + lastRowid = (page.last[rowidKey] as num).toInt(); + if (page.length < exportPageSize) return; } + } + + Future copyRows( + String table, { + String? where, + List whereArgs = const [], + }) => + copyPaged(table, where: where, whereArgs: whereArgs); + + Future copyRawRange(int startSec, int endSec) async { + // The day's 1 Hz rows stream page by page, and each page's RR beats are + // pulled and written before the next page is read — so peak residency is + // one page of `decoded_onehz` plus its beats, not a whole day of both. + await copyPaged( + 'decoded_onehz', + where: 'rec_ts >= ? AND rec_ts < ?', + whereArgs: [startSec, endSec], + onPage: (page) async { + final counters = [ + for (final row in page) + if (row['counter'] != null) row['counter'], + ]; + if (counters.isEmpty) return; + // CHUNKED `IN (…)`: even one page's counters can approach + // SQLITE_MAX_VARIABLE_NUMBER, and a full day is 86,400 — two orders + // of magnitude past it, so one giant statement could never bind. + // (This never surfaced only because the missing `version:` above + // aborted the export earlier.) + for (final chunk in _sqlVarChunks(counters)) { + final placeholders = List.filled(chunk.length, '?').join(','); + final rr = await src.rawQuery( + 'SELECT * FROM decoded_rr WHERE counter IN ($placeholders)', + chunk, + ); + if (rr.isEmpty) continue; + await out.transaction((txn) async { + final batch = txn.batch(); + for (final row in rr) { + batch.insert( + 'decoded_rr', + Map.from(row), + conflictAlgorithm: ConflictAlgorithm.replace, + ); + } + await batch.commit(noResult: true); + }); + } + }, + ); await copyRows( 'samples', where: 'ts >= ? AND ts < ?', @@ -3234,13 +3288,42 @@ class LocalDb { final counts = {}; try { for (final t in tables) { - List> rows; + // PAGED SOURCE READ — never `SELECT *` a whole table. + // + // This used to be a single `src.query(t)`. sqflite serialises an entire + // result set into Java objects on the platform side BEFORE any of it + // crosses the channel, so importing another device's `decoded_onehz` + // (86,400 rows per day of history) materialised the whole table on the + // 256 MB Dalvik heap at once — and then held it live for the duration + // of the insert loop below. That is the production + // `java.lang.OutOfMemoryError` seen on 0.9.19 from ImportScreen + // ("target footprint 268435456, growth limit 268435456"); the OOM + // surfaced on whichever thread happened to allocate next, which is why + // it was blamed on a BLE binder callback. + // + // Keyset pagination on `rowid` (none of these tables is WITHOUT ROWID), + // NOT LIMIT/OFFSET — OFFSET re-scans the skipped prefix on every page, + // which is quadratic over a full history. + // `_rowid` is aliased into the projection so the cursor can advance; + // it is filtered straight back out when the row is rebuilt below, + // because the `cols.contains(e.key)` guard only admits real + // destination columns and no table has a column by that name. + const pageSize = 2000; + const rowidKey = '_rowid'; + var lastRowid = 0; + Future>> nextPage() => src.rawQuery( + 'SELECT rowid AS $rowidKey, * FROM $t ' + 'WHERE rowid > ? ORDER BY rowid ASC LIMIT ?', + [lastRowid, pageSize], + ); + + List> firstPage; try { - rows = await src.query(t); + firstPage = await nextPage(); } catch (_) { continue; // table absent in the source export } - if (rows.isEmpty) { + if (firstPage.isEmpty) { counts[t] = 0; continue; } @@ -3263,52 +3346,68 @@ class LocalDb { }; } var copied = 0; - await db.transaction((txn) async { - // CHUNKED, for the same reason commitSyncBatch chunks: sqflite - // serialises a whole batch's args into ONE platform message. A - // full-history import is hundreds of thousands of rows, and the - // orphan guard below adds an op per decoded_onehz row on top. - const chunkOps = 4000; - var batch = txn.batch(); - var ops = 0; - Future flush() async { - if (ops == 0) return; - await batch.commit(noResult: true); - batch = txn.batch(); - ops = 0; - } - - for (final r in rows) { - final row = { - for (final e in r.entries) - if (cols.contains(e.key)) e.key: e.value, - }; - if (row.isEmpty) continue; - if (t == 'day_result' && - protectedKeys.contains( - '${row['day_id']}|${row['algo_version']}', - )) { - continue; // locally finalized — never overwritten by an import + var page = firstPage; + // ONE TRANSACTION PER PAGE, not per table. The whole-table transaction + // this replaces could only ever commit if the entire table fit in + // memory first, which is the bug. Per-page commits keep peak residency + // at one page, and the import stays safe to interrupt or repeat: every + // write is INSERT OR REPLACE keyed on the row's own identity, so a + // re-run converges to the same state, and each decoded_onehz row's + // orphan guard is still queued in the SAME transaction as the row it + // guards — the invariant that matters is per-row, not per-table. + while (page.isNotEmpty) { + await db.transaction((txn) async { + // CHUNKED, for the same reason commitSyncBatch chunks: sqflite + // serialises a whole batch's args into ONE platform message, and + // the orphan guard below adds an op per decoded_onehz row on top. + const chunkOps = 4000; + var batch = txn.batch(); + var ops = 0; + Future flush() async { + if (ops == 0) return; + await batch.commit(noResult: true); + batch = txn.batch(); + ops = 0; } - // ORPHAN GUARD ON THE IMPORT PATH. A plain replace-insert into - // decoded_onehz bypasses _queueDecodedOneHz entirely, so a foreign - // row colliding on UNIQUE(rec_ts) (different counter) or on the - // `counter` PRIMARY KEY (different second) evicted a local row and - // stranded its decoded_rr beats — the exact leak the ingest path is - // guarded against, wide open here. Queue the SAME guard, in the - // same batch/transaction, right before the row. - if (t == 'decoded_onehz') { - final counter = (row['counter'] as num?)?.toInt(); - final recTs = (row['rec_ts'] as num?)?.toInt(); - if (counter == null || recTs == null) continue; - ops += _queueOrphanGuard(batch, counter: counter, recTs: recTs); + + for (final r in page) { + final row = { + for (final e in r.entries) + if (cols.contains(e.key)) e.key: e.value, + }; + if (row.isEmpty) continue; + if (t == 'day_result' && + protectedKeys.contains( + '${row['day_id']}|${row['algo_version']}', + )) { + continue; // locally finalized — never overwritten by an import + } + // ORPHAN GUARD ON THE IMPORT PATH. A plain replace-insert into + // decoded_onehz bypasses _queueDecodedOneHz entirely, so a + // foreign row colliding on UNIQUE(rec_ts) (different counter) or + // on the `counter` PRIMARY KEY (different second) evicted a local + // row and stranded its decoded_rr beats — the exact leak the + // ingest path is guarded against, wide open here. Queue the SAME + // guard, in the same batch/transaction, right before the row. + if (t == 'decoded_onehz') { + final counter = (row['counter'] as num?)?.toInt(); + final recTs = (row['rec_ts'] as num?)?.toInt(); + if (counter == null || recTs == null) continue; + ops += _queueOrphanGuard(batch, counter: counter, recTs: recTs); + } + batch.insert(t, row, conflictAlgorithm: ConflictAlgorithm.replace); + copied++; + if (++ops >= chunkOps) await flush(); } - batch.insert(t, row, conflictAlgorithm: ConflictAlgorithm.replace); - copied++; - if (++ops >= chunkOps) await flush(); - } - await flush(); - }); + await flush(); + }); + // Advance past the last row this page actually delivered. Read the + // cursor BEFORE dropping the page, and stop on a short page rather + // than issuing one more query to discover the end. + lastRowid = (page.last[rowidKey] as num).toInt(); + if (page.length < pageSize) break; + page = await nextPage(); + } counts[t] = copied; } } finally { diff --git a/lib/sync/background_sync.dart b/lib/sync/background_sync.dart index 81445aa1..d9847ee2 100644 --- a/lib/sync/background_sync.dart +++ b/lib/sync/background_sync.dart @@ -123,6 +123,7 @@ Future runHeadlessSync({BandLease? lease}) async { try { await DerivationEngine( log: (l) => debugPrint('[bgsync-derive] $l'), + background: true, ).run(await _loadProfile()); } catch (e) { debugPrint('[bgsync] derive skipped: $e'); diff --git a/lib/sync/ios_bg_task.dart b/lib/sync/ios_bg_task.dart index 6c8bc737..19416adf 100644 --- a/lib/sync/ios_bg_task.dart +++ b/lib/sync/ios_bg_task.dart @@ -90,7 +90,8 @@ class IosBgTask { try { final profile = await _loadProfile(); final engine = DerivationEngine( - log: (l) => debugPrint('[ios-bgtask-derive] $l')); + log: (l) => debugPrint('[ios-bgtask-derive] $l'), + background: true); await engine.run(profile, heavy: true); // Baseline-dirty rescan on the iOS BGTask tick: refresh // baseline-dependent scalars on recent finalized days if the @@ -106,7 +107,8 @@ class IosBgTask { try { final profile = await _loadProfile(); final engine = DerivationEngine( - log: (l) => debugPrint('[ios-bgrefresh-derive] $l')); + log: (l) => debugPrint('[ios-bgrefresh-derive] $l'), + background: true); await engine.run(profile, heavy: false); await _refreshWidgetSnapshot(profile); } catch (e) { diff --git a/lib/telemetry/jank_policy.dart b/lib/telemetry/jank_policy.dart new file mode 100644 index 00000000..8a5e4d67 --- /dev/null +++ b/lib/telemetry/jank_policy.dart @@ -0,0 +1,90 @@ +// jank_policy.dart — pure decision layer for the frame-jank watchdog. +// +// WHY THIS EXISTS (production bug, Crashlytics 0.9.19/0.9.20): +// The watchdog used to gate on `FrameTiming.totalSpan`, which is the span from +// the frame's vsync START to its raster END. That span includes time the engine +// was not doing any work at all — most importantly the gap across an app +// resume, where the "frame" straddles however long the app sat in the +// background. The result was reports like: +// +// Slow frame: 16358ms (build=0 raster=8) +// +// i.e. a 16-SECOND "stutter" in which the app did 8 ms of actual work. That +// single false-positive class became the top issue by impacted-user count on +// both platforms, burying real signal underneath it. +// +// The honest measure of "the user saw a stutter" is the work the engine +// actually did on the frame: build (UI thread) + raster (GPU thread). Those are +// the two costs the app controls and the two a fix would move. `totalSpan` is +// still reported as CONTEXT — a large total with a small build+raster is +// interesting (scheduling delay, resume, thermal throttle), it is just not a +// jank report. +// +// Kept separate from TelemetryService so the rule is unit-testable without a +// SchedulerBinding, a Firebase app, or a real frame. + +/// The verdict for one frame: should it be reported, and with what numbers. +class JankVerdict { + const JankVerdict({ + required this.report, + required this.workMs, + required this.buildMs, + required this.rasterMs, + required this.totalMs, + }); + + /// True when this frame represents real engine work above the threshold. + final bool report; + + /// build + raster — the cost the app is actually responsible for. + final int workMs; + + final int buildMs; + final int rasterMs; + + /// vsync-start → raster-end. Context only; never the trigger. + final int totalMs; + + /// How much of the span was NOT engine work (scheduling delay, resume gap, + /// throttling). Large values here with a small [workMs] are the signature of + /// the false positive this policy exists to suppress. + int get idleMs { + final gap = totalMs - workMs; + return gap > 0 ? gap : 0; + } + + String get message => + 'Slow frame: ${workMs}ms of engine work ' + '(build=$buildMs raster=$rasterMs, total span=${totalMs}ms)'; +} + +/// Pure jank rule. [thresholdMs] applies to build+raster, NOT to the total span. +/// +/// The default of 700 ms is unchanged from the original watchdog, but it now +/// means "the engine burned 700 ms on one frame" rather than "700 ms elapsed", +/// which is roughly two orders of magnitude rarer and always actionable. +class JankPolicy { + const JankPolicy({this.thresholdMs = 700}); + + final int thresholdMs; + + JankVerdict evaluate({ + required int buildMs, + required int rasterMs, + required int totalMs, + }) { + // Defend against the negative/absurd durations a clock change or a + // backgrounded engine can hand us — treat them as "no work observed" + // rather than letting them underflow the sum into a false trigger. + final b = buildMs > 0 ? buildMs : 0; + final r = rasterMs > 0 ? rasterMs : 0; + final work = b + r; + return JankVerdict( + report: work >= thresholdMs, + workMs: work, + buildMs: b, + rasterMs: r, + totalMs: totalMs > 0 ? totalMs : 0, + ); + } +} diff --git a/lib/telemetry/telemetry_service.dart b/lib/telemetry/telemetry_service.dart index 02b86ae3..160cc3cb 100644 --- a/lib/telemetry/telemetry_service.dart +++ b/lib/telemetry/telemetry_service.dart @@ -27,6 +27,7 @@ import 'package:firebase_performance/firebase_performance.dart'; import 'package:firebase_analytics/firebase_analytics.dart'; import '../cloud/companion_client.dart'; +import 'jank_policy.dart'; /// A band-side snapshot AppState supplies (it owns the live DeviceState). typedef BandSnapshot = Map Function(); @@ -263,35 +264,49 @@ class TelemetryService { /// Turn invisible UI jank into real Crashlytics non-fatal reports. Flutter /// itself already measures every frame's build+raster cost — we just have - /// to listen. A frame at/above [thresholdMs] reads as a visible stutter to - /// the user; this is what actually answers "the app froze while scrolling" - /// reports, which Crashlytics otherwise never sees at all (freezing isn't a - /// crash). Throttled to at most one report per [minGapSeconds] so a rough - /// patch (e.g. a long scroll over a busy screen) doesn't spam the outbox — - /// still enough to catch the pattern without drowning it. + /// to listen. A frame whose ENGINE WORK (build + raster) is at/above + /// [thresholdMs] reads as a visible stutter to the user; this is what + /// actually answers "the app froze while scrolling" reports, which + /// Crashlytics otherwise never sees at all (freezing isn't a crash). + /// Throttled to at most one report per [minGapSeconds] so a rough patch + /// (e.g. a long scroll over a busy screen) doesn't spam the outbox — still + /// enough to catch the pattern without drowning it. + /// + /// The threshold deliberately does NOT apply to `FrameTiming.totalSpan`. + /// totalSpan includes time the engine did nothing — above all the gap across + /// an app resume — which produced reports like "Slow frame: 16358ms (build=0 + /// raster=8)" and made this the noisiest issue in the project. See + /// [JankPolicy] for the full rationale; totalSpan is still attached as + /// context so a scheduling-delay pattern remains visible. void installJankWatchdog({int thresholdMs = 700, int minGapSeconds = 30}) { + final policy = JankPolicy(thresholdMs: thresholdMs); SchedulerBinding.instance.addTimingsCallback((List timings) { if (_jankThrottle != null) return; for (final t in timings) { - final totalMs = t.totalSpan.inMilliseconds; - if (totalMs < thresholdMs) continue; + final v = policy.evaluate( + buildMs: t.buildDuration.inMilliseconds, + rasterMs: t.rasterDuration.inMilliseconds, + totalMs: t.totalSpan.inMilliseconds, + ); + if (!v.report) continue; _jankThrottle = Timer(Duration(seconds: minGapSeconds), () { _jankThrottle = null; }); - final buildMs = t.buildDuration.inMilliseconds; - final rasterMs = t.rasterDuration.inMilliseconds; breadcrumb( - 'slow_frame total=${totalMs}ms build=${buildMs}ms raster=${rasterMs}ms', + 'slow_frame work=${v.workMs}ms build=${v.buildMs}ms ' + 'raster=${v.rasterMs}ms total=${v.totalMs}ms', ); recordNonFatal( - Exception('Slow frame: ${totalMs}ms (build=$buildMs raster=$rasterMs)'), + Exception(v.message), StackTrace.current, reason: 'jank_watchdog', ); record(kind: 'event', level: 'warn', message: 'slow_frame', context: { - 'total_ms': totalMs, - 'build_ms': buildMs, - 'raster_ms': rasterMs, + 'work_ms': v.workMs, + 'build_ms': v.buildMs, + 'raster_ms': v.rasterMs, + 'total_ms': v.totalMs, + 'idle_ms': v.idleMs, }); break; // one report per callback batch is enough signal } diff --git a/lib/ui/import/import_screen.dart b/lib/ui/import/import_screen.dart index 59a68ef9..23504595 100644 --- a/lib/ui/import/import_screen.dart +++ b/lib/ui/import/import_screen.dart @@ -9,6 +9,7 @@ import 'package:file_picker/file_picker.dart'; import 'package:flutter/material.dart'; +import 'package:flutter/services.dart' show PlatformException; import 'package:provider/provider.dart'; import '../../state/app_state.dart'; @@ -22,10 +23,20 @@ class ImportScreen extends StatefulWidget { class _ImportScreenState extends State { bool _busy = false; + + /// True while the native file picker is on screen. Distinct from [_busy] + /// (which means "an import is running"): the cards must be inert for BOTH, + /// but only [_busy] shows the progress card. + bool _picking = false; String? _progress; String? _result; String? _error; + /// The option cards are inert while EITHER a picker is open or an import is + /// running — the window between those two states is exactly where the + /// double-tap `already_active` crash lived. + bool get _locked => _busy || _picking; + void _set(VoidCallback fn) { if (mounted) setState(fn); } @@ -34,14 +45,41 @@ class _ImportScreenState extends State { // types and rejects unmapped ones like `db` (and often `csv`) with "Unsupported // filter". The importers are content-aware (NOOP/WHOOP detect by CSV header, // Edge opens the file as SQLite), so we accept any file and validate on parse. + // + // RE-ENTRANCY: `_busy` only goes true once an import is already RUNNING, i.e. + // after the picker returns — so while the native sheet is open the three + // option cards stayed live. A second tap (the sheet takes a beat to appear on + // a cold platform channel, so users do tap twice) called pickFiles again and + // file_picker threw `PlatformException(already_active)` out of an unawaited + // context, crashing the app. Guarded twice over: `_picking` disables the + // cards for the duration, and the catch below refuses to let any picker + // platform failure become a fatal — a picker that won't open is a message, + // not a crash. Future> _pick({bool multiple = false}) async { - final res = await FilePicker.platform.pickFiles( - type: FileType.any, - allowMultiple: multiple, - withData: false, - ); - if (res == null) return const []; - return [for (final f in res.files) if (f.path != null) f.path!]; + if (_picking) return const []; + _set(() => _picking = true); + try { + final res = await FilePicker.platform.pickFiles( + type: FileType.any, + allowMultiple: multiple, + withData: false, + ); + if (res == null) return const []; + return [for (final f in res.files) if (f.path != null) f.path!]; + } on PlatformException catch (e) { + // `already_active` is the benign double-tap race — the first picker is + // still up and will deliver the user's choice, so say nothing. Anything + // else is worth showing. + if (e.code != 'already_active') { + _set(() => _error = 'Could not open the file picker: ${e.message ?? e.code}'); + } + return const []; + } catch (e) { + _set(() => _error = 'Could not open the file picker: $e'); + return const []; + } finally { + _set(() => _picking = false); + } } Future _run(String label, Future Function() task, @@ -113,14 +151,14 @@ class _ImportScreenState extends State { icon: OsIcon.heartRate, title: 'Import from NOOP', body: 'Raw 1 Hz CSV — re-analyzed end-to-end on this phone.', - onTap: _busy ? null : _importNoop, + onTap: _locked ? null : _importNoop, ), const SizedBox(height: Sp.x3), ImportOptionCard( icon: OsIcon.server, title: 'Import from Edge backup', body: 'A .db exported from another OpenStrap device.', - onTap: _busy ? null : _importEdge, + onTap: _locked ? null : _importEdge, ), const SizedBox(height: Sp.x3), ImportOptionCard( @@ -128,7 +166,7 @@ class _ImportScreenState extends State { title: 'Import from WHOOP', tag: 'BETA', body: 'WHOOP export CSVs — derived summaries only.', - onTap: _busy ? null : _importWhoop, + onTap: _locked ? null : _importWhoop, ), ]), const SizedBox(height: Sp.x2), diff --git a/test/db_paged_import_export_test.dart b/test/db_paged_import_export_test.dart new file mode 100644 index 00000000..4e40e2ad --- /dev/null +++ b/test/db_paged_import_export_test.dart @@ -0,0 +1,265 @@ +// Paged source reads on the import/export paths, run against the REAL LocalDb +// over sqflite_ffi. +// +// THE BUG (production, Crashlytics 0.9.19, Android): +// java.lang.OutOfMemoryError — "Failed to allocate a 32 byte allocation with +// 27360 free bytes and 26KB until OOM, target footprint 268435456, growth +// limit 268435456", with `current_screen: ImportScreen`. +// +// `importFromDbFile` read each source table with ONE unbounded `src.query(t)`, +// and `exportDaysDb`'s `copyRawRange` read a whole day of `decoded_onehz` in +// one statement. sqflite serialises an entire result set into Java objects +// BEFORE any of it crosses the platform channel, so a full-history +// `decoded_onehz` (86,400 rows per day) had to fit on the 256 MB Dalvik heap +// all at once — and was then held live for the duration of the insert loop. +// +// Both are now keyset-paged on rowid at 2000 rows. These tests drive row counts +// ACROSS several page boundaries (and off-by-one around them) to prove paging +// neither drops nor duplicates rows, since a broken cursor is silent: you get +// a partial import, not an error. + +import 'dart:io'; + +import 'package:flutter_test/flutter_test.dart'; +import 'package:path/path.dart' as p; +import 'package:path_provider_platform_interface/path_provider_platform_interface.dart'; +import 'package:sqflite_common_ffi/sqflite_ffi.dart'; +import 'package:openstrap_edge/data/db.dart'; + +/// The page size used by both paged readers in db.dart. The tests deliberately +/// straddle it rather than assuming any particular value is "big enough". +const int kPageSize = 2000; + +class _FakePathProvider extends PathProviderPlatform { + _FakePathProvider(this.root); + final String root; + @override + Future getTemporaryPath() async => root; + @override + Future getApplicationSupportPath() async => root; + @override + Future getApplicationDocumentsPath() async => root; + @override + Future getApplicationCachePath() async => root; + @override + Future getLibraryPath() async => root; + @override + Future getDownloadsPath() async => root; +} + +void main() { + late Directory tmp; + late String srcPath; + + setUpAll(() async { + sqfliteFfiInit(); + databaseFactory = databaseFactoryFfi; + tmp = await Directory.systemTemp.createTemp('openstrap_paged_'); + PathProviderPlatform.instance = _FakePathProvider(tmp.path); + LocalDb.dbName = 'openstrap_paged_test.db'; + await databaseFactory.deleteDatabase( + p.join(await databaseFactory.getDatabasesPath(), LocalDb.dbName), + ); + srcPath = p.join(await databaseFactory.getDatabasesPath(), 'paged_src.db'); + }); + + tearDownAll(() async { + await LocalDb.close(); + final dir = await databaseFactory.getDatabasesPath(); + await databaseFactory.deleteDatabase(p.join(dir, LocalDb.dbName)); + await databaseFactory.deleteDatabase(srcPath); + if (await tmp.exists()) await tmp.delete(recursive: true); + }); + + /// Builds a foreign export holding [rows] seconds of 1 Hz data, each with one + /// RR beat, starting at [startTs] / counter 1. + Future buildSource(int rows, {required int startTs}) async { + await databaseFactory.deleteDatabase(srcPath); + final src = await databaseFactory.openDatabase(srcPath); + await src.execute(''' + CREATE TABLE decoded_onehz ( + counter INTEGER PRIMARY KEY, rec_ts INTEGER NOT NULL, + hr INTEGER NOT NULL, ax REAL NOT NULL, ay REAL NOT NULL, + az REAL NOT NULL, spo2_red_raw INTEGER NOT NULL, + spo2_ir_raw INTEGER NOT NULL, skin_temp_raw INTEGER NOT NULL) + '''); + await src.execute(''' + CREATE TABLE decoded_rr ( + counter INTEGER NOT NULL, beat_index INTEGER NOT NULL, + rr_ts_ms INTEGER NOT NULL, rr_ms INTEGER NOT NULL, + PRIMARY KEY (counter, beat_index)) + '''); + final batch = src.batch(); + for (var i = 0; i < rows; i++) { + final counter = i + 1; + final ts = startTs + i; + batch.insert('decoded_onehz', { + 'counter': counter, + 'rec_ts': ts, + // hr encodes the index so a shuffled/duplicated row is detectable. + 'hr': 40 + (i % 100), + 'ax': 0.0, + 'ay': 0.0, + 'az': 1.0, + 'spo2_red_raw': 0, + 'spo2_ir_raw': 0, + 'skin_temp_raw': 0, + }); + batch.insert('decoded_rr', { + 'counter': counter, + 'beat_index': 0, + 'rr_ts_ms': ts * 1000, + 'rr_ms': 800 + (i % 50), + }); + } + await batch.commit(noResult: true); + await src.close(); + } + + Future clearLocal() async { + final db = await LocalDb.instance; + await db.delete('decoded_rr'); + await db.delete('decoded_onehz'); + } + + group('importFromDbFile pages the source without losing rows', () { + // Straddle the boundary from both sides plus a clean multiple, which is + // where an off-by-one cursor (`rowid >=` instead of `>`, or stopping on a + // full final page) shows up. + for (final rows in [ + kPageSize - 1, + kPageSize, + kPageSize + 1, + kPageSize * 2, + kPageSize * 2 + 37, + ]) { + test('$rows rows import exactly once', () async { + await clearLocal(); + const startTs = 1786100000; + await buildSource(rows, startTs: startTs); + + final counts = await LocalDb.importFromDbFile(srcPath); + expect(counts['decoded_onehz'], rows, + reason: 'every source row must be reported as copied'); + + final db = await LocalDb.instance; + final n = (await db.rawQuery( + 'SELECT COUNT(*) c FROM decoded_onehz', + )).first['c']; + expect(n, rows, reason: 'no rows dropped at a page boundary'); + + final beats = (await db.rawQuery( + 'SELECT COUNT(*) c FROM decoded_rr', + )).first['c']; + expect(beats, rows, reason: 'RR beats page alongside their frames'); + + // Endpoints prove the cursor covered the whole range, not just a prefix. + final lo = (await db.rawQuery( + 'SELECT MIN(rec_ts) v FROM decoded_onehz', + )).first['v']; + final hi = (await db.rawQuery( + 'SELECT MAX(rec_ts) v FROM decoded_onehz', + )).first['v']; + expect(lo, startTs); + expect(hi, startTs + rows - 1); + + // A duplicated page would show up as a gap in distinct timestamps. + final distinct = (await db.rawQuery( + 'SELECT COUNT(DISTINCT rec_ts) c FROM decoded_onehz', + )).first['c']; + expect(distinct, rows); + + // Nothing stranded: the orphan guard still runs per row under paging. + final orphans = (await db.rawQuery( + 'SELECT COUNT(*) c FROM decoded_rr ' + 'WHERE counter NOT IN (SELECT counter FROM decoded_onehz)', + )).first['c']; + expect(orphans, 0); + }); + } + + test('re-importing the same file is idempotent, not doubled', () async { + await clearLocal(); + final rows = kPageSize + 500; + await buildSource(rows, startTs: 1786200000); + + await LocalDb.importFromDbFile(srcPath); + await LocalDb.importFromDbFile(srcPath); + + final db = await LocalDb.instance; + final n = (await db.rawQuery( + 'SELECT COUNT(*) c FROM decoded_onehz', + )).first['c']; + expect(n, rows, + reason: 'per-page transactions must stay INSERT OR REPLACE-safe, so ' + 'an interrupted import is always safe to re-run'); + }); + + test('an empty source table reports zero and writes nothing', () async { + await clearLocal(); + await buildSource(0, startTs: 1786300000); + final counts = await LocalDb.importFromDbFile(srcPath); + expect(counts['decoded_onehz'], 0); + final db = await LocalDb.instance; + expect( + (await db.rawQuery('SELECT COUNT(*) c FROM decoded_onehz')).first['c'], + 0, + ); + }); + }); + + group('exportDaysDb pages a whole day out', () { + test('a multi-page day round-trips every row and beat', () async { + await clearLocal(); + // ~2.4 pages inside a single local day, so copyRawRange must page. + const rows = kPageSize * 2 + 800; + // Anchor mid-day UTC so the local-day window contains the whole run + // regardless of the machine's timezone offset. + final startTs = + DateTime.utc(2026, 5, 14, 2).millisecondsSinceEpoch ~/ 1000; + await buildSource(rows, startTs: startTs); + await LocalDb.importFromDbFile(srcPath); + + final db = await LocalDb.instance; + final localDay = (await db.rawQuery( + "SELECT strftime('%Y-%m-%d', rec_ts, 'unixepoch', 'localtime') d, " + 'COUNT(*) c FROM decoded_onehz GROUP BY d ORDER BY c DESC LIMIT 1', + )).first; + final dayId = localDay['d'] as String; + final expectedRows = (localDay['c'] as num).toInt(); + expect(expectedRows, greaterThan(kPageSize), + reason: 'the test is meaningless unless the day spans pages'); + + final outPath = await LocalDb.exportDaysDb({dayId}); + expect(await File(outPath).exists(), isTrue); + + final out = await databaseFactory.openDatabase(outPath); + try { + final got = (await out.rawQuery( + 'SELECT COUNT(*) c FROM decoded_onehz', + )).first['c']; + expect(got, expectedRows, + reason: 'every row of the day must survive the paged export'); + + final beats = (await out.rawQuery( + 'SELECT COUNT(*) c FROM decoded_rr', + )).first['c']; + expect(beats, expectedRows, + reason: 'each page\'s beats are pulled before the next page'); + + final distinct = (await out.rawQuery( + 'SELECT COUNT(DISTINCT rec_ts) c FROM decoded_onehz', + )).first['c']; + expect(distinct, expectedRows, reason: 'no page copied twice'); + } finally { + await out.close(); + await databaseFactory.deleteDatabase(outPath); + } + }); + }); + + test('the degraded RR fallback truncation counter starts clean', () async { + // A non-zero value means some window computed HRV from truncated beats. + expect(LocalDb.decodedRrFallbackTruncations, 0); + }); +} diff --git a/test/derive_pacing_test.dart b/test/derive_pacing_test.dart new file mode 100644 index 00000000..3d2b8b9e --- /dev/null +++ b/test/derive_pacing_test.dart @@ -0,0 +1,66 @@ +// Regression tests for foreground vs background derivation pacing. +// +// The production bug these lock down (Crashlytics 0.9.20, iOS 27): the engine +// ran 3 concurrent day-lanes with a 90 s per-day wall-clock timeout REGARDLESS +// of whether it was in the foreground or inside a throttled BGProcessingTask. +// In background that combination reliably produced `day_blocks_failed` +// TimeoutExceptions for days that were computing correctly, just slowly — +// three lanes dividing one throttled CPU slice three ways, each then blowing a +// budget calibrated for an un-throttled core. + +import 'package:flutter_test/flutter_test.dart'; +import 'package:openstrap_edge/compute/derive_pacing.dart'; + +void main() { + const fg = DerivePacing(background: false); + const bg = DerivePacing(background: true); + + group('concurrency', () { + test('background is ALWAYS one lane, however many cores exist', () { + for (final cores in [1, 2, 4, 8, 16]) { + expect(bg.concurrency(cores), 1, + reason: 'a throttled slot gains nothing from $cores lanes'); + } + }); + + test('foreground uses spare cores, capped', () { + expect(fg.concurrency(1), 1); + expect(fg.concurrency(2), 2); + expect(fg.concurrency(3), 3); + expect(fg.concurrency(8), DerivePacing.maxForegroundConcurrency); + expect(fg.concurrency(64), DerivePacing.maxForegroundConcurrency); + }); + + test('a nonsense core count still yields a usable lane count', () { + expect(fg.concurrency(0), 1); + expect(fg.concurrency(-4), 1); + expect(bg.concurrency(0), 1); + }); + }); + + group('per-day timeout', () { + test('background gets a materially larger budget than foreground', () { + expect(bg.perDayTimeout, greaterThan(fg.perDayTimeout)); + }); + + test('foreground budget is unchanged at 90s', () { + expect(fg.perDayTimeout, const Duration(seconds: 90)); + }); + + test('background budget covers the observed throttled overrun', () { + // The reported failures were days exceeding 90 s under throttling. The + // background budget must clear that by a real margin, while still being + // a bound (a hung day must not run forever). + expect(bg.perDayTimeout, greaterThanOrEqualTo(const Duration(minutes: 3))); + expect(bg.perDayTimeout, lessThanOrEqualTo(const Duration(minutes: 10))); + }); + }); + + test('the two modes differ in BOTH dimensions, not just one', () { + // Widening the timeout alone would leave three lanes fighting for one + // slice; serializing alone would leave the 90 s cliff in place. The fix is + // only correct as a pair. + expect(bg.concurrency(8), isNot(equals(fg.concurrency(8)))); + expect(bg.perDayTimeout, isNot(equals(fg.perDayTimeout))); + }); +} diff --git a/test/jank_policy_test.dart b/test/jank_policy_test.dart new file mode 100644 index 00000000..5d73bc5d --- /dev/null +++ b/test/jank_policy_test.dart @@ -0,0 +1,90 @@ +// Regression tests for the frame-jank watchdog rule. +// +// The production bug these lock down: the watchdog triggered on +// `FrameTiming.totalSpan`, so an app resume — where the "frame" straddles the +// whole time the app was backgrounded — reported as a multi-second stutter +// despite near-zero engine work. Real numbers from Crashlytics 0.9.20: +// "Slow frame: 16358ms (build=0 raster=8)". That class of report was the top +// issue by impacted users on both platforms. + +import 'package:flutter_test/flutter_test.dart'; +import 'package:openstrap_edge/telemetry/jank_policy.dart'; + +void main() { + const policy = JankPolicy(); // 700 ms of engine work + + group('JankPolicy does not report idle time as jank', () { + test('the exact production false positive stays silent', () { + // 16.4 s total span, 8 ms of actual work — an app resume, not a stutter. + final v = policy.evaluate(buildMs: 0, rasterMs: 8, totalMs: 16358); + expect(v.report, isFalse); + expect(v.workMs, 8); + expect(v.idleMs, 16350); + }); + + test('a long span with sub-threshold work stays silent', () { + final v = policy.evaluate(buildMs: 59, rasterMs: 164, totalMs: 3791); + expect(v.report, isFalse, reason: '223ms of work is not a 700ms stutter'); + }); + + test('the other production sample stays silent too', () { + final v = policy.evaluate(buildMs: 5, rasterMs: 1, totalMs: 1469); + expect(v.report, isFalse); + }); + }); + + group('JankPolicy still reports real jank', () { + test('a genuinely expensive build trips the threshold', () { + final v = policy.evaluate(buildMs: 900, rasterMs: 20, totalMs: 950); + expect(v.report, isTrue); + expect(v.workMs, 920); + }); + + test('build and raster combine — neither alone would trip it', () { + final v = policy.evaluate(buildMs: 400, rasterMs: 350, totalMs: 800); + expect(v.report, isTrue, reason: '750ms of combined work is a stutter'); + }); + + test('an expensive raster pass alone trips it', () { + final v = policy.evaluate(buildMs: 10, rasterMs: 1200, totalMs: 1300); + expect(v.report, isTrue); + }); + + test('exactly at the threshold reports', () { + expect(policy.evaluate(buildMs: 700, rasterMs: 0, totalMs: 700).report, + isTrue); + expect(policy.evaluate(buildMs: 699, rasterMs: 0, totalMs: 699).report, + isFalse); + }); + }); + + group('JankPolicy is defensive about absurd input', () { + test('negative durations are floored at zero, never underflowed', () { + final v = policy.evaluate(buildMs: -5000, rasterMs: 10, totalMs: -1); + expect(v.report, isFalse); + expect(v.workMs, 10); + expect(v.totalMs, 0); + expect(v.idleMs, 0, reason: 'idle can never go negative'); + }); + + test('idle is zero when work exceeds the reported span', () { + final v = policy.evaluate(buildMs: 800, rasterMs: 100, totalMs: 50); + expect(v.idleMs, 0); + expect(v.report, isTrue); + }); + }); + + test('a custom threshold applies to work, not span', () { + const strict = JankPolicy(thresholdMs: 100); + expect(strict.evaluate(buildMs: 60, rasterMs: 50, totalMs: 120).report, + isTrue); + expect(strict.evaluate(buildMs: 1, rasterMs: 1, totalMs: 99999).report, + isFalse); + }); + + test('the message names engine work first and span as context', () { + final v = policy.evaluate(buildMs: 800, rasterMs: 100, totalMs: 5000); + expect(v.message, contains('900ms of engine work')); + expect(v.message, contains('total span=5000ms')); + }); +} From 899428521ec47d1cfc6bf2516e5e2fcdae7802ae Mon Sep 17 00:00:00 2001 From: abdulsaheel Date: Wed, 29 Jul 2026 00:27:13 +0530 Subject: [PATCH 2/2] fix(db): narrow the import's table-skip catch to genuinely-absent tables MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Addresses bot review on #163. The import's first-page read caught EVERYTHING and treated it as "this export doesn't carry that table" — so corruption, a truncated or malformed source file, or an I/O error all skipped the table silently, `counts[t]` was never set, and the summed total then reported a PARTIAL import as a success. Silent partial success on someone's health history is the worst available outcome. Now only `isNoSuchTableError()` skips; everything else propagates. Narrowing this had a real regression risk worth a test: the fixture only creates decoded_onehz + decoded_rr, so every other table in the import list already hits the missing-table path on every import test. Had `isNoSuchTableError()` not matched sqflite's actual exception, importing a partial export would have started THROWING instead of skipping — and that would have ridden in on tests that appear to be about paging. Now asserted by name. (Used sqflite's own predicate rather than matching 'no such table' in a `toString()`, which is not stable across platforms.) Also, from the same review: - `copyPaged` hands [onPage] rows with the `_rowid` cursor column already stripped, so a callback can insert what it is given. Today's only callback reads `row['counter']`, but the raw-row API was a standing invitation to a "no such column: _rowid" bug. Drops a redundant per-row map rebuild too. - Documented why the static truncation counter is sound at this call site (every sqflite call needs the root isolate's platform channel, and the only caller reads on the main isolate and ships pages to the worker via `worker.send`) and what breaks it, because the previous comment implied the opposite and led a reviewer to a wrong conclusion. - Documented the paging-column tradeoff where it lives. Paging on rowid rather than the filtered column means a filtered page walks the rowid chain instead of driving off the rec_ts index. It stays cheap because both factors are bounded — decoded_onehz is pruned to rawRetentionDays behind the data edge, and the never-pruned per-day tables are hundreds of rows. Measured ~10 ms for the worst case (the exhaustion page that scans to the end of the table) on a real 435k-row ledger. 990 tests pass; analyze clean. --- lib/data/db.dart | 58 ++++++++++++++++++++++----- test/db_paged_import_export_test.dart | 20 +++++++++ 2 files changed, 67 insertions(+), 11 deletions(-) diff --git a/lib/data/db.dart b/lib/data/db.dart index f2f42d81..3454ad70 100644 --- a/lib/data/db.dart +++ b/lib/data/db.dart @@ -2652,8 +2652,16 @@ class LocalDb { ); // Never truncate silently — a short read here means missing beats, which // shows up downstream as understated HRV rather than as an error. db.dart - // takes no telemetry dependency (it has to run inside compute isolates), so - // the fact is recorded as a counter the Diagnostics screen can surface. + // deliberately takes no telemetry dependency, so the fact is recorded as a + // plain counter the Diagnostics screen can surface. + // + // A static field is sound HERE specifically: every sqflite call needs the + // root isolate's platform channel, and this method's only caller + // (`DerivationEngine._prepare`) reads on the main isolate and ships each + // page to the compute worker with `worker.send`. Increments therefore land + // in the same isolate that reads them. Move this read into an isolate and + // the counter silently stops working — pass the count back over the port + // instead of reaching for a static. if (rows.length >= fallbackBeatCap) { decodedRrFallbackTruncations++; } @@ -3013,6 +3021,23 @@ class LocalDb { /// Streams `table` (optionally filtered) into [out] one page at a time, /// calling [onPage] with each page after it has been written. + /// + /// [onPage] receives rows with the `$rowidKey` cursor column ALREADY + /// stripped, so a callback can insert what it is handed without tripping + /// over a column no destination table has. The cursor is read off the raw + /// page here and never leaves this function. + /// + /// PAGING COLUMN: rowid, not the filtered column, so one helper serves + /// every table regardless of what it is filtered on. That means a filtered + /// page walks the rowid chain and tests the predicate per row rather than + /// driving off the `rec_ts`/`ts` index. It stays cheap because both factors + /// are small: `decoded_onehz` is bounded by `rawRetentionDays` (days, not + /// years — it is pruned behind the data edge), and the never-pruned tables + /// paged per day here are hundreds to thousands of rows. Measured on a real + /// 435k-row ledger the worst case — the exhaustion page that scans to the + /// end of the table — is ~10 ms. Revisit only if retention grows a lot; + /// per-table cursors would need a composite `(ts, rowid)` key for the + /// non-unique columns, which is not worth the complexity today. Future copyPaged( String table, { String? where, @@ -3029,22 +3054,25 @@ class LocalDb { [lastRowid, ...whereArgs, exportPageSize], ); if (page.isEmpty) return; - await out.transaction((txn) async { - final batch = txn.batch(); - for (final row in page) { - final clean = { + final clean = [ + for (final row in page) + { for (final e in row.entries) if (e.key != rowidKey) e.key: e.value, - }; + }, + ]; + await out.transaction((txn) async { + final batch = txn.batch(); + for (final row in clean) { batch.insert( table, - clean, + row, conflictAlgorithm: ConflictAlgorithm.replace, ); } await batch.commit(noResult: true); }); - if (onPage != null) await onPage(page); + if (onPage != null) await onPage(clean); lastRowid = (page.last[rowidKey] as num).toInt(); if (page.length < exportPageSize) return; } @@ -3320,8 +3348,16 @@ class LocalDb { List> firstPage; try { firstPage = await nextPage(); - } catch (_) { - continue; // table absent in the source export + } on DatabaseException catch (e) { + // ONLY "this export doesn't carry that table" is skippable. A blanket + // catch here made every read failure — corruption, a truncated or + // malformed source file, an I/O error — look identical to an absent + // table: the table was skipped, `counts[t]` was never set, and the + // summed total then reported a PARTIAL import as a success. Silent + // partial success on someone's health history is the worst available + // outcome, so anything that is not a missing table now propagates. + if (e.isNoSuchTableError()) continue; + rethrow; } if (firstPage.isEmpty) { counts[t] = 0; diff --git a/test/db_paged_import_export_test.dart b/test/db_paged_import_export_test.dart index 4e40e2ad..45758243 100644 --- a/test/db_paged_import_export_test.dart +++ b/test/db_paged_import_export_test.dart @@ -195,6 +195,26 @@ void main() { 'an interrupted import is always safe to re-run'); }); + test('a source missing most tables skips them without throwing', () async { + // The fixture only ever creates decoded_onehz + decoded_rr, so every + // other table in the import list raises "no such table" on its first + // page. That path is narrowed to `DatabaseException.isNoSuchTableError()` + // precisely so a genuine read failure can no longer masquerade as an + // absent table — which means if that predicate ever stops matching + // sqflite's real exception, importing a partial export would start + // THROWING instead of skipping. Asserted explicitly rather than left to + // ride implicitly on the paging tests above. + await clearLocal(); + await buildSource(10, startTs: 1786400000); + + final counts = await LocalDb.importFromDbFile(srcPath); + + expect(counts['decoded_onehz'], 10, reason: 'present tables still copy'); + expect(counts.containsKey('journal'), isFalse, + reason: 'a table absent from the source is skipped, not reported as ' + 'an empty success'); + }); + test('an empty source table reports zero and writes nothing', () async { await clearLocal(); await buildSource(0, startTs: 1786300000);