feat(profiling): P3 per-segment query profiler timing + scenarios (LOC-68)

docs/perf/ondevice-query-profiler/PR-P3.md

@@ -0,0 +1,44 @@
+# PR P3 — 세그먼트 타이밍 + 3시나리오 × 2레인
+
+- 브랜치: `feat/loc-68-profiler-timing`
+- Linear: [LOC-68](https://linear.app/loceract/issue/LOC-68)
+- 상태: 🟦 진행 (PR 열림 예정, iPhone 실기 profile 런 green)
+
+## 스코프
+실 ONNX 자산 example 앱에서 쿼리 단계를 **격리 계측**하는 디바이스 프로파일러 본체.
+- `example/lib/profiling/query_profiler.dart` — `SourceRagService.searchMeta`(:933-995) 경로를 미러링해 embed / activate(스위치) / search / hydrate를 단계별로 `Stopwatch` 계측. 엔진 private 헬퍼 2개를 인용과 함께 복제: `_indexPath`(FNV-1a, :283-309), `_toInt64List`(FRB generalized Int64List, :261-268). `activateOnly`/`deleteOnDiskIndex`로 결정적 cold 셋업, hit의 sourceId 반환으로 필터 fail-closed.
+- `example/integration_test/query_profile_measure_test.dart` — 측정 엔트리(단독 파일). pure_cold(evicted cold activate) / pure_warm(2레인) / switching_cold(A→B→A) × Unfiltered·Filtered(i8). P1의 `SegmentSamples`/`QueryProfileRun` 집계, 콘솔에 행 단위 `PROFILE_CSV`.
+- `example/test_driver/integration_test.dart` — `flutter drive` 엔트리(profile 빌드 필수).
+- `example/pubspec.yaml` — `flutter_rust_bridge ^2.11.1`(프로파일러가 FRB i64 리스트 생성에 필요).
+
+## 측정 방법 (중요: `flutter test` 아님 → `flutter drive`)
+`flutter test`는 빌드 모드를 debug로 하드핀 → cargokit debug → **fallback 백엔드**(출시 `vector_faer,vector_quant_i8` 미적용)라 baseline 무효. profile 빌드는 `flutter drive`로만:
+
+```
+cd example && flutter drive \
+  --driver=test_driver/integration_test.dart \
+  --target=integration_test/query_profile_measure_test.dart \
+  --profile -d 00008110-001524992E38801E
+```
+
+fail-closed: `kDebugMode` skip+assert(프로필 강제) / 필터레인 hit sourceId ⊆ 요청 / 세그먼트별 N>0.
+
+## 결과 (iPhone iOS 26.5, profile, 컬렉션당 500 docs, topK=10)
+| lane | category | embed p50/p95 | activate | search p50/p95 | hydrate p50/p95 |
+|---|---|---|---|---|---|
+| unfiltered | pure_cold (n=1) | 25.2 | **247.3** | 2.20 | 0.42 |
+| unfiltered | pure_warm (n=30) | **26.7 / 36.7** | — | 1.60 / 2.08 | 0.27 / 0.41 |
+| filtered(i8) | pure_warm (n=30) | **27.6 / 37.6** | — | 0.76 / 0.92 | 0.19 / 0.30 |
+| unfiltered | switching_cold (n=30) | 25.7 / 37.0 | (로그 트렁케이션 유실) | 1.47 / 1.90 | (유실) |
+
+- embed(ONNX)가 warm 정상상태 지배(~27ms, 타 세그먼트 15–37배). cold는 activate 지배(247ms). 필터 i8 search가 unfiltered보다 빠름(0.76 vs 1.60ms).
+- 전체 결과/디바이스/방법은 [LOC-68 코멘트](https://linear.app/loceract/issue/LOC-68) 참조.
+
+## 받은 피드백 / 디버그 로그 (실기에서만 드러남)
+- 어드버서리얼 리뷰가 분석 단계에서 2 critical 차단: ① `flutter test --profile`는 무효(빌드 debug 고정) → `flutter drive` + test_driver 추가. ② 필터레인의 `scoped_exact_scan_rows>0` 단언은 항상 실패(엔진이 그 카운터를 증가시키지 않음, 셰일드 러스트 테스트가 ==0 단언) → sourceId⊆요청 검사로 대체.
+- 실기 런에서 ③ 기본 테스트 타임아웃 30s 초과(2×500 ONNX 임베드) → `Timeout(15분)`. ④ `clearAllData` 비동기 재초기화가 첫 seed와 경합 → `database is locked` → 측정을 **자체 파일 분리** + init 전 DB 삭제(clearAllData 미사용). ⑤ 콘솔이 큰 단일 print를 잘라먹음 → CSV 행 단위 print.
+- DDS 간헐 실패: profile 런 성공 1·실패 2 관측, kill 후 재실행.
+
+## 리스크 / 롤백 / 다음
+- 동작 코드 변경 없음(example 프로파일링 + test_driver + dep). 롤백: PR revert.
+- 다음: **P4(LOC-69)** = JSON/CSV export + 메타(baseline 산출). 본 PR 위에 스택.

docs/perf/ondevice-query-profiler/README.md

@@ -23,8 +23,8 @@ vector_math 커널 슬라이스는 거의 최적임을 확인했으나 **온디
 |----|------|--------|------|
 | 스펙+계획 | DESIGN + PLAN | [LOC-65](https://linear.app/loceract/issue/LOC-65) | 🟩 머지(#69) |
 | P1 | report 모델 + JSON/CSV (host-TDD) | [LOC-66](https://linear.app/loceract/issue/LOC-66) | 🟩 머지(#70, [PR-P1.md](PR-P1.md)) |
-| P2 | example integration_test 배선 + A/B 픽스처 | [LOC-67](https://linear.app/loceract/issue/LOC-67) | 🟦 진행([PR-P2.md](PR-P2.md), 기기 green) |
-| P3 | 세그먼트 타이밍 + 3시나리오 + metrics 스냅샷 | [LOC-68](https://linear.app/loceract/issue/LOC-68) | ⬜ TODO |
+| P2 | example integration_test 배선 + A/B 픽스처 | [LOC-67](https://linear.app/loceract/issue/LOC-67) | 🟩 머지(#71, [PR-P2.md](PR-P2.md)) |
+| P3 | 세그먼트 타이밍 + 3시나리오 + metrics 스냅샷 | [LOC-68](https://linear.app/loceract/issue/LOC-68) | 🟦 진행([PR-P3.md](PR-P3.md), 기기 green) |
 | P4 | JSON/CSV export + 로그 + 메타 (baseline 산출) | [LOC-69](https://linear.app/loceract/issue/LOC-69) | ⬜ TODO |
 | P5 | (조건부) Phase-2 드릴다운 — 지배 버킷별 | [LOC-70](https://linear.app/loceract/issue/LOC-70) | ⏸ 데이터 게이트 |
 

example/integration_test/query_profile_measure_test.dart

@@ -0,0 +1,245 @@
+import 'dart:io';
+
+import 'package:flutter/foundation.dart'
+    show kDebugMode, kProfileMode, kReleaseMode;
+import 'package:flutter_test/flutter_test.dart';
+import 'package:integration_test/integration_test.dart';
+import 'package:path_provider/path_provider.dart';
+import 'package:mobile_rag_engine/mobile_rag_engine.dart';
+import 'package:mobile_rag_engine_example/profiling/query_fixture.dart';
+import 'package:mobile_rag_engine_example/profiling/query_profiler.dart';
+import 'package:mobile_rag_engine_example/profiling/query_profile_report.dart';
+
+// On-device RAG query profiler — P3 (LOC-68) measurement.
+//
+// Runs ALONE in its own process (separate from the P2 smoke) under flutter
+// drive in PROFILE mode, so the shipped `vector_faer,vector_quant_i8` backend
+// is exercised (flutter test hard-pins debug = fallback backend = invalid):
+//
+//   cd example && flutter drive \
+//       --driver=test_driver/integration_test.dart \
+//       --target=integration_test/query_profile_measure_test.dart \
+//       --profile -d <device-id>
+//
+// Clean state is established by DELETING the DB files before initialize (not
+// clearAllData, whose async re-init races the first seed and trips
+// "database is locked"). Per-collection index files are removed after init.
+void main() {
+  IntegrationTestWidgetsFlutterBinding.ensureInitialized();
+
+  const measuredDocs = 500; // representative; raise for scan-bound runs
+  const warmup = 5;
+  const measured = 30;
+  const topK = 10;
+
+  test(
+    'profiler: pure_cold / pure_warm / switching_cold x 2 lanes',
+    () async {
+      _assertProfileMode();
+
+      // Fresh DB without clearAllData: delete the SQLite files BEFORE
+      // initialize so the engine starts clean and nothing races the seed.
+      final docsDir = await getApplicationDocumentsDirectory();
+      final dbStem = '${docsDir.path}/profile.sqlite';
+      for (final p in [dbStem, '$dbStem-wal', '$dbStem-shm', '$dbStem-journal']) {
+        final f = File(p);
+        if (await f.exists()) await f.delete();
+      }
+
+      await MobileRag.initialize(
+        tokenizerAsset: 'assets/tokenizer.json',
+        modelAsset: 'assets/model.onnx',
+        databaseName: 'profile.sqlite',
+        deferIndexWarmup: true,
+      );
+
+      final ids = await QueryFixture.seed(docsPerCollection: measuredDocs);
+      expect(ids[QueryFixture.collectionA]!.length, measuredDocs);
+      expect(ids[QueryFixture.collectionB]!.length, measuredDocs);
+
+      final profiler = QueryProfiler(dbPath: MobileRag.instance.dbPath);
+      final q = QueryFixture.unfilteredQueries;
+      final runs = <QueryProfileRun>[];
+
+      final meta = <String, Object?>{
+        'build_mode':
+            kReleaseMode ? 'release' : (kProfileMode ? 'profile' : 'debug'),
+        'features': 'vector_faer,vector_quant_i8', // shipped in profile/release
+        'docs_per_collection': measuredDocs,
+        'top_k': topK,
+        'vector_weight': profiler.vectorWeight,
+        'bm25_weight': profiler.bm25Weight,
+        // Cold-activate semantics differ per cell: pure_cold rebuilds A's index
+        // from the DB (on-disk index deleted, slot evicted); switching_cold then
+        // loads A from disk (pure_cold's activate re-saved it). Both are genuine
+        // cold costs; the switch is the realistic production figure.
+        'cold_note': 'pure_cold=rebuild-from-db; switching_cold=load-from-disk',
+      };
+
+      // Per-collection index files survive across runs; delete them so the first
+      // activate rebuilds the current corpus from the DB, then evict A from the
+      // single global HNSW slot so pure_cold's activate is genuinely cold.
+      await profiler.deleteOnDiskIndex(QueryFixture.collectionA);
+      await profiler.deleteOnDiskIndex(QueryFixture.collectionB);
+      await profiler.activateOnly(QueryFixture.collectionB); // active := B (A evicted)
+
+      /// Run one (lane, category) cell.
+      /// - [activateOnce]: single cold shot measures the activate segment (pure_cold).
+      /// - [activatePerIter]: re-activate A every iter after evicting it (switching_cold).
+      Future<QueryProfileRun> runCell({
+        required String lane,
+        required String category,
+        required int warmupN,
+        required int measuredN,
+        bool activateOnce = false,
+        bool activatePerIter = false,
+        List<int>? sourceIds,
+      }) async {
+        final measuresActivate = activateOnce || activatePerIter;
+        final segs = {
+          for (final n in ['embed', 'search', 'hydrate',
+              if (measuresActivate) 'activate'])
+            n: SegmentSamples(n),
+        };
+        final allowed = sourceIds?.toSet();
+
+        // Warm cells: ensure A is active, then warm caches (discarded). Cold
+        // cells (warmupN == 0) skip this so the measured shot stays cold.
+        if (warmupN > 0) {
+          await profiler.activateOnly(QueryFixture.collectionA);
+          for (var i = 0; i < warmupN; i++) {
+            await profiler.measureOnce(
+              collectionId: QueryFixture.collectionA,
+              query: q[i % q.length],
+              sourceIds: sourceIds,
+            );
+          }
+        }
+
+        QueryProfiler.resetIo(); // I/O snapshot reflects measured iters only
+        var minHits = -1;
+        for (var i = 0; i < measuredN; i++) {
+          if (activatePerIter) {
+            // Evict A (no query, so collection-B I/O does not pollute the
+            // snapshot) so the measured activate(A) pays the real switch cost.
+            await profiler.activateOnly(QueryFixture.collectionB);
+          }
+          final r = await profiler.measureOnce(
+            collectionId: QueryFixture.collectionA,
+            query: q[i % q.length],
+            sourceIds: sourceIds,
+            activate: activateOnce || activatePerIter,
+          );
+          r.ms.forEach((k, v) => segs[k]?.add(v));
+          final hitCount = r.hitSourceIds.length;
+          if (minHits < 0 || hitCount < minHits) minHits = hitCount;
+          // Fail-closed (filtered lane): every hit must come from the requested
+          // sources — proves the filter actually applied. (Replaces the
+          // scoped_exact_scan_rows counter, which the engine never increments.)
+          if (allowed != null) {
+            expect(r.hitSourceIds.every(allowed.contains), isTrue,
+                reason: '$lane/$category returned a hit outside requested '
+                    'sourceIds — filter not applied');
+          }
+        }
+        final io = profiler.snapshotIo();
+
+        // Fail-closed: a wrong index path or empty corpus would return 0 hits.
+        expect(minHits, greaterThan(0),
+            reason: '$lane/$category returned 0 hits — wrong index path/corpus');
+        return QueryProfileRun(
+            lane: lane, category: category, segments: segs, io: io, meta: meta);
+      }
+
+      // Pure Cold (first query, cold index build) — unfiltered one-shot.
+      // Runs first; it leaves collection A active for the warm cells below.
+      runs.add(await runCell(
+        lane: 'unfiltered',
+        category: 'pure_cold',
+        warmupN: 0,
+        measuredN: 1,
+        activateOnce: true,
+      ));
+
+      // Pure Warm (collection already active) — both lanes.
+      runs.add(await runCell(
+        lane: 'unfiltered',
+        category: 'pure_warm',
+        warmupN: warmup,
+        measuredN: measured,
+      ));
+      runs.add(await runCell(
+        lane: 'filtered',
+        category: 'pure_warm',
+        warmupN: warmup,
+        measuredN: measured,
+        sourceIds: ids[QueryFixture.collectionA]!.take(3).toList(),
+      ));
+
+      // Switching Cold (A -> B -> A each iter) — unfiltered (expensive path).
+      runs.add(await runCell(
+        lane: 'unfiltered',
+        category: 'switching_cold',
+        warmupN: warmup,
+        measuredN: measured,
+        activatePerIter: true,
+      ));
+
+      // Fail-closed: every cell has at least one sample per segment.
+      for (final r in runs) {
+        for (final s in r.segments.values) {
+          expect(s.samplesMs.length, greaterThan(0),
+              reason: '${r.lane}/${r.category}/${s.segment}');
+        }
+      }
+
+      // P3 deliverable: per-segment p50/p95 to the device log (greppable CSV).
+      // P4 adds JSON/CSV export to the app documents dir on top of this.
+      _emitReport(QueryProfileReport(runs: runs));
+    },
+    // Seeding 2x500 real ONNX embeddings + the measured loops far exceed the
+    // default 30s per-test timeout; give it generous headroom.
+    timeout: const Timeout(Duration(minutes: 15)),
+    // `flutter test` is always debug -> fallback backend. Skip there so an
+    // invalid baseline is never produced; runs only under flutter drive --profile.
+    skip: kDebugMode
+        ? 'Measurement requires `flutter drive --profile` '
+            '(flutter test is debug = fallback backend = invalid baseline).'
+        : false,
+  );
+}
+
+/// Fail-closed backend gate (defense-in-depth alongside the test-level skip).
+/// Debug builds compile the cargokit debug profile = fallback Rust backend (no
+/// vector_faer / vector_quant_i8), so any debug baseline is invalid. kDebugMode
+/// is a compile-time const, false under a real profile/release build.
+void _assertProfileMode() {
+  if (kDebugMode) {
+    fail(
+      'Query profiler must run in PROFILE/RELEASE via flutter drive.\n'
+      'Run: cd example && flutter drive '
+      '--driver=test_driver/integration_test.dart '
+      '--target=integration_test/query_profile_measure_test.dart '
+      '--profile -d <device-id>\n'
+      'Debug builds use the cargokit debug profile = fallback Rust backend '
+      '(no vector_faer / vector_quant_i8), so the baseline would be invalid. '
+      'Aborting to avoid a fake-green baseline. '
+      '(detected: kDebugMode=$kDebugMode, kProfileMode=$kProfileMode, '
+      'kReleaseMode=$kReleaseMode)',
+    );
+  }
+}
+
+/// Print the report to the device log in greppable blocks. Each CSV row is a
+/// SEPARATE print: the device console truncates long single lines, so one big
+/// multi-line print(toCsv()) loses the tail (e.g. switching_cold's activate).
+void _emitReport(QueryProfileReport report) {
+  for (final line in report.toCsv().trimRight().split('\n')) {
+    // ignore: avoid_print
+    print('PROFILE_CSV $line');
+  }
+  for (final r in report.runs) {
+    // ignore: avoid_print
+    print('PROFILE_IO ${r.lane}/${r.category} ${r.io}');
+  }
+}

example/integration_test/query_profile_test.dart

@@ -3,17 +3,18 @@ import 'package:integration_test/integration_test.dart';
 import 'package:mobile_rag_engine/mobile_rag_engine.dart';
 import 'package:mobile_rag_engine_example/profiling/query_fixture.dart';
 
-// On-device RAG query profiler — P2.3 smoke entrypoint.
+// On-device RAG query profiler — P2 smoke entrypoint.
 //
-// Validates the device pipeline: engine init (real ONNX), A/B fixture seed.
-// NOTE: `flutter test integration_test` builds DEBUG by default, which uses
-// the cargokit debug profile (fallback Rust backend). The P3/P4 measurement
-// runs must use profile/release so the shipped `vector_faer,vector_quant_i8`
-// backend is exercised.
+// Validates the device pipeline: engine init (real ONNX) + A/B fixture seed.
+// Runs fine in debug:
+//   flutter test integration_test/query_profile_test.dart -d <device-id>
+//
+// The P3/P4 MEASUREMENT lives in query_profile_measure_test.dart and must run
+// under `flutter drive --profile` (profile build => shipped vector_faer/
+// vector_quant_i8 backend; flutter test hard-pins debug = fallback backend).
 void main() {
   IntegrationTestWidgetsFlutterBinding.ensureInitialized();
 
-  // Smoke uses a small corpus for speed; P3 scales this up.
   const docsPerCollection = 40;
 
   // Non-UI integration test: use test() (not testWidgets) so the widget-tester