Reduce repeated startup reads and trace cached graph stages

app/journal_graph_feed_plan.ml

@@ -11,6 +11,7 @@ type day_feed =
 
 type feed_scan =
   { root_session : int64
+  ; root_started : Mtime_clock.counter option
   ; root_generation : int64
   ; root_start_day : int option
   ; root_before_day : int option
@@ -387,6 +388,12 @@ let root_feed_response ~ports scan complete =
     ; continuation = root_date_continuation scan
     ; prioritized_day = scan.root_skipped_day
     } in
+  Option.iter (fun began ->
+    ports.report "startup-feed"
+      [ "requestGeneration", `String (Int64.to_string scan.root_generation)
+      ; "complete", `Bool complete
+      ; "elapsedMs", `Float (Mtime.Span.to_float_ns (Mtime_clock.count began) /. 1_000_000.)
+      ]) scan.root_started;
   ports.report "runtime-feed-result"
     [ "requestGeneration", `String (Int64.to_string scan.root_generation)
     ; "complete", `Bool complete
@@ -652,6 +659,8 @@ let start_feed_scan t ~ports ~cursor ~root_limit ~day_limit ~request_generation
     then t.initial_feed_spec <- Some (root_limit, day_limit);
     let scan =
       { root_session = t.feed_session
+      ; root_started = (if Sys.getenv_opt "JOURNAL_STARTUP_DIAGNOSTICS" = Some "1"
+          then Some (Mtime_clock.counter ()) else None)
       ; root_generation = request_generation
       ; root_start_day = start_day
       ; root_before_day = before_day

docs/development/startup-diagnostics.md

@@ -0,0 +1,78 @@
+# Cached graph startup diagnostics
+
+Set `JOURNAL_STARTUP_DIAGNOSTICS=1` for a launched process to enable stage timing.
+Logging is off by default; the entry point always captures one raw Mach timestamp
+before checking the diagnostic flag. It does not enable networking, change service
+startup ordering, or write graph data. With an already installed app on an explicitly selected iOS
+Simulator:
+
+```sh
+SIMCTL_CHILD_JOURNAL_STARTUP_DIAGNOSTICS=1 xcrun simctl launch \
+  --stdout="$EVIDENCE_DIR/startup.stdout" --stderr="$EVIDENCE_DIR/startup.stderr" \
+  "$SIM_UDID" com.logseq.journal
+```
+
+Use an external evidence directory. Terminate the app separately before each
+process-cold sample; retain its container and Keychain. Do not use a finite-lived
+`simctl launch --console` observer whose termination can also terminate the app.
+Verify the selected graph and Current / Ready / Open state before timing; first
+download, sign-in and unlock are separate scenarios.
+
+## Stages
+
+`journal-startup:` stderr records contain only fixed stage names and numeric
+timings. Swift uses monotonic process uptime and records begin/end pairs or
+point markers:
+
+| Stage | Boundary |
+| --- | --- |
+| `host_prepare` | Application services setup and startup payload preparation |
+| `backend_init` | Native LUI backend construction |
+| `ocaml_start` | Synchronous `lui_ocaml_start`, including callbacks it executes |
+| `initial_platform_requests` | Initial platform reply barrier |
+| `root_appeared` | SwiftUI runtime root's `onAppear` callback |
+| `timeline_acknowledged` | Native receipt of the timeline presentation acknowledgement |
+
+Worker `mirror_inspection` includes local retirement recovery and durable mirror
+metadata inspection. Its `clock=wall` duration uses the existing Unix clock (and
+can be affected by wall-clock adjustment); other durations use monotonic clocks.
+Overlay `local_attach` encloses the owned database open;
+its subspans are `outbox_read`, `receipt_validation`, `outbox_migration`,
+`storage_open` and `datascript_restore`. Overlay records include wall elapsed
+time and **process-wide** CPU time, not per-fiber CPU usage.
+
+The existing bounded `journal-timeline:` reporter additionally emits
+`stage: "startup-feed"` when enabled. `elapsedMs` measures from the feed scan's
+creation (before the first root/day query) to a feed publication. `complete`
+distinguishes incremental publications from the completed result;
+`requestGeneration` correlates publications within a scan. These records add no
+graph identifiers, credentials or journal content. Other existing log categories
+can contain private metadata; review and redact raw logs before sharing them.
+
+## Interpretation
+
+- `main_raw` records Mach ticks captured at the first source statement in the
+  entry point, before diagnostic flag, Foundation or string initialization. It is
+  emitted after `main_enter` and converted using `mach_timebase_info`; compare
+  timestamps, not log order. Verify the compiled entry when attributing startup.
+  It is not the first machine instruction or the exec boundary.
+- `main_enter` is the first application logging call before SwiftUI `App.main`,
+  after the loader has entered the executable. It includes diagnostic flag/clock
+  initialization overhead, and does not isolate dyld or framework initializers.
+  `app_init` encloses the App initializer body; its nested `native_services` span
+  includes platform construction. `app_body` and `host_body` mark body evaluation,
+  which may repeat. Select their first occurrence for launch attribution.
+  `host_task_entered` precedes the setup guard and existing `host_prepare` span.
+  These markers do not change the order of service construction or startup work.
+- Spans can nest or overlap; do not add their durations as serial launch time.
+  In particular, `local_attach` includes its subspans.
+- A span ending means its call returned or unwound, not that the operation
+  succeeded. Pair with the normal outcome/error observations.
+- Point markers are lifecycle callbacks, **not first displayed content frames**.
+  Use screenshots/recording or Instruments for that boundary and for pre-main
+  time, which these application-level markers do not measure.
+- Do not subtract timestamps across clock sources. Feed durations include queue,
+  worker query and projection time; they are not isolated SQLite query timings.
+- Timings are diagnostic overhead-bearing samples, not a performance gate. Bind
+  results to the actual build manifest and final source revision; experimental
+  host-restamped Simulator results do not establish device performance or ABI.

logseq_db_worker/lib/effect_runner/effect_runner.ml

@@ -4,6 +4,16 @@ let report_warning message =
   try output_string stderr message; flush stderr with _ -> ()
 ;;
 
+let startup_timed stage action =
+  if Sys.getenv_opt "JOURNAL_STARTUP_DIAGNOSTICS" <> Some "1" then action ()
+  else
+    let began = Unix.gettimeofday () in
+    Fun.protect action ~finally:(fun () ->
+      report_warning (Printf.sprintf
+        "journal-startup: source=worker stage=%s phase=end clock=wall elapsed_ms=%.3f\n"
+        stage ((Unix.gettimeofday () -. began) *. 1000.)))
+;;
+
 module Upload = Logseq_db_worker_pure_reducer.Asset_upload
 module Core = Logseq_db_worker_pure_reducer.Core
 module Database = Logseq_overlay_db.Database
@@ -165,12 +175,17 @@ let clear_id_token_cache cache message =
   cancel_token_flight cache message
 ;;
 
+let revoke_id_token_cache cache =
+  clear_id_token_cache cache Logseq_db_types.Failure_diagnostic.(
+    create ~operation:"httpTransport" ~reason:"cancelled" () |> encode)
+;;
+
 let reconcile_authenticated_user cache ~user_id =
   Eio.Mutex.use_rw ~protect:true cache.lock (fun () ->
     if cache.authenticated_user <> user_id
     then (
       cache.authenticated_user <- user_id;
-      clear_id_token_cache cache "ID token request is no longer current."))
+      revoke_id_token_cache cache))
 ;;
 
 let reusable_token cache owner =
@@ -214,7 +229,7 @@ let acquire_id_token cache ~(account : Sync.account_scope) =
       else (
         (match cache.authenticated_user with
          | Some user_id when not (String.equal user_id owner.user_id) ->
-           clear_id_token_cache cache "ID token request is no longer current."
+           revoke_id_token_cache cache
          | None | Some _ -> ());
         cache.authenticated_user <- Some owner.user_id;
         match reusable_token cache owner with
@@ -223,7 +238,7 @@ let acquire_id_token cache ~(account : Sync.account_scope) =
           (match cache.flight with
            | Some flight when flight.request.owner = owner -> Await_token flight.outcome
            | Some _ ->
-             clear_id_token_cache cache "ID token request is no longer current.";
+             revoke_id_token_cache cache;
              start_token_request cache owner
            | None -> start_token_request cache owner)))
   in
@@ -2495,6 +2510,7 @@ let release_host_copy t ~registration =match t.host_copy with
 
 let handle_sync_worker_effect t = function
   | Sync.Inspect_mirror request ->
+    startup_timed "mirror_inspection" (fun () ->
     let recovery = with_staging_lock t (fun () -> recover_local_retirements t request.scope) in
     (match recovery with
      | Error message -> Error (effect_error message)
@@ -2515,7 +2531,7 @@ let handle_sync_worker_effect t = function
         | Overlay.Absent _ ->
           Ok (sync_result ~event:(Sync.Mirror_inspected (Mirror_absent request.scope)) ())
         | Available _ ->
-             Ok (sync_result ~event:(Sync.Mirror_inspected (Mirror_available request)) ()))))
+             Ok (sync_result ~event:(Sync.Mirror_inspected (Mirror_available request)) ())))))
   | Activate_snapshot request ->
     let key = Graph.Uuid.to_string (Sync.snapshot_activation_scope request).graph_id in
     (match Hashtbl.find_opt t.inspections key with

logseq_overlay_db/lib/database.ml

@@ -18,6 +18,18 @@ type dependencies =
   ; limits : Types.capability_limits
   }
 
+let startup_timed dependencies stage action =
+  if Sys.getenv_opt "JOURNAL_STARTUP_DIAGNOSTICS" <> Some "1" then action ()
+  else
+    let began = dependencies.monotonic_ns () in
+    let cpu = Sys.time () in
+    Fun.protect action ~finally:(fun () ->
+      let elapsed_ms = Int64.sub (dependencies.monotonic_ns ()) began |> Int64.to_float in
+      report_warning (Printf.sprintf
+        "journal-startup: source=overlay stage=%s phase=end elapsed_ms=%.3f process_cpu_ms=%.3f\n"
+        stage (elapsed_ms /. 1_000_000.) ((Sys.time () -. cpu) *. 1000.)))
+;;
+
 type durable_mirror_location =
   { database_path : string
   ; graph_id : Graph.Uuid.t
@@ -1757,41 +1769,6 @@ let page_of_database ?cache database uuid =
   Option.bind (entity_of_uuid database uuid) (page_record_of_entity ?cache database)
 ;;
 
-let entity_datoms_for_ids database entities =
-  let entities = List.sort_uniq Int.compare entities in
-  let result = Hashtbl.create (List.length entities) in
-  let add datom =
-    let preceding =
-      Hashtbl.find_opt result datom.Datascript.e |> Option.value ~default:[]
-    in
-    Hashtbl.replace result datom.e (datom :: preceding)
-  in
-  (match entities with
-   | [] -> ()
-   | first :: _ ->
-     let last = List.hd (List.rev entities) in
-     if last - first <= List.length entities * 32
-     then (
-       let wanted = Hashtbl.create (List.length entities) in
-       List.iter (fun entity -> Hashtbl.add wanted entity ()) entities;
-       let rec consume sequence =
-         match sequence () with
-         | Seq.Nil -> ()
-         | Seq.Cons (datom, rest) ->
-           if datom.Datascript.e > last
-           then ()
-           else (
-             if Hashtbl.mem wanted datom.e then add datom;
-             consume rest)
-       in
-       consume (Datascript.seek_datoms database Datascript.Eavt ~e:first ()))
-     else List.iter (fun entity -> List.iter add (entity_datoms database entity)) entities);
-  Hashtbl.iter
-    (fun entity datoms -> Hashtbl.replace result entity (List.rev datoms))
-    result;
-  result
-;;
-
 let status_entity database = function
   | Types.Status_uuid uuid -> entity_of_uuid database uuid
   | Legacy_status_ident ident -> entity_of_ident database ident
@@ -3296,7 +3273,7 @@ let structural_fields_reader database =
       fields
 ;;
 
-let authoritative_child_entity_facts ?datoms_by_uuid (snapshot : snapshot) parent =
+let authoritative_child_entity_facts (snapshot : snapshot) parent =
   let database = Option.get snapshot.authoritative_database in
   match entity_of_uuid database parent with
   | None -> Seq.empty
@@ -3310,39 +3287,12 @@ let authoritative_child_entity_facts ?datoms_by_uuid (snapshot : snapshot) paren
         ()
       |> Seq.map (fun (datom : Datascript.datom) -> datom.e)
     in
-    let fields =
-      match datoms_by_uuid with
-      | None ->
-        (* Structural eligibility requires UUID and order only. Full payloads
-           are needed only by callers explicitly requesting hydration inputs. *)
-        let read = structural_fields_reader database in
-        Seq.map
-          (fun entity ->
-             let uuid, order = read entity in
-             entity, None, uuid, order)
-          entities
-      | Some _ ->
-        let entities = List.of_seq entities in
-        let datoms_by_entity = entity_datoms_for_ids database entities in
-        entities
-        |> List.to_seq
-        |> Seq.map (fun entity ->
-          let datoms =
-            Hashtbl.find_opt datoms_by_entity entity |> Option.value ~default:[]
-          in
-          ( entity
-          , Some datoms
-          , one_in_datoms datoms "block/uuid"
-          , one_in_datoms datoms "block/order" ))
-    in
-    fields
-    |> Seq.filter_map (fun (entity, datoms, uuid, order) ->
+    let read = structural_fields_reader database in
+    entities
+    |> Seq.filter_map (fun entity ->
+      let uuid, order = read entity in
       match Option.bind uuid uuid_of_value, Option.bind order string_of_value with
       | Some uuid, Some order when not (block_is_tombstoned snapshot uuid) ->
-        Option.iter
-          (fun table ->
-             Hashtbl.replace table (Graph.Uuid.to_string uuid) (Option.get datoms))
-          datoms_by_uuid;
         Some (order, uuid, entity)
       | _ -> None)
 ;;
@@ -4365,14 +4315,7 @@ let paginate_children snapshot ~parent ~limit ~offset =
       xor_digest membership_accumulator (Graph.Uuid.to_string uuid ^ "\000" ^ order);
       fact
     in
-    let authoritative_datoms = Hashtbl.create requested in
-    let authoritative_facts =
-      authoritative_child_entity_facts
-        ~datoms_by_uuid:authoritative_datoms
-        snapshot
-        parent
-      |> Seq.map (fun (order, uuid, _) -> order, uuid)
-    in
+    let authoritative_facts = authoritative_child_facts snapshot parent in
     let facts, total =
       Overlay_read.bounded_members
         ~maximum:requested
@@ -4384,20 +4327,15 @@ let paginate_children snapshot ~parent ~limit ~offset =
       | 0, _ | _, [] -> values
       | count, _ :: rest -> drop (count - 1) rest
     in
-    let cache = hydration_cache (Option.get snapshot.authoritative_database) in
+    let cache =
+      lazy (hydration_cache ~index_idents:false (Option.get snapshot.authoritative_database))
+    in
     let rec take count reversed = function
       | [] -> List.rev reversed
       | _ when count = 0 -> List.rev reversed
       | (_, uuid) :: rest ->
         let reversed =
-          let initial =
-            Option.bind
-              (Hashtbl.find_opt authoritative_datoms (Graph.Uuid.to_string uuid))
-              (block_record_of_datoms_with_cache
-                 (Option.get snapshot.authoritative_database)
-                 cache)
-          in
-          match logical_block_at ~cache ~initial snapshot uuid with
+          match logical_block_at ~cache:(Lazy.force cache) snapshot uuid with
           | Some block ->
             Types.{ block; revision = logical_block_revision uuid (Some block) }
             :: reversed
@@ -5941,7 +5879,8 @@ let open_owned ~sw dependencies inspection ~graph_name ownership =
   if not (Sys.file_exists path)
   then Error Types.Attachment_stale
   else (
-    match read_outbox path, validate_durable_receipts path with
+    match startup_timed dependencies "outbox_read" (fun () -> read_outbox path),
+          startup_timed dependencies "receipt_validation" (fun () -> validate_durable_receipts path) with
     | Error message, _ -> Error (Types.Corrupt_outbox message)
     | _, Error message -> Error (Types.Corrupt_mutation_receipt message)
     | Ok (encoded, durable_revision), Ok () ->
@@ -5953,10 +5892,11 @@ let open_owned ~sw dependencies inspection ~graph_name ownership =
        | Ok (outbox, legacy_revision) ->
          let sync_revision = Option.value durable_revision ~default:legacy_revision in
          let durable_outbox = durable_outbox_rows outbox in
-         (match migrate_outbox path ~revision:sync_revision ~expected_records:encoded durable_outbox with
+         (match startup_timed dependencies "outbox_migration" (fun () ->
+            migrate_outbox path ~revision:sync_revision ~expected_records:encoded durable_outbox) with
           | Error message -> Error (Types.Corrupt_outbox message)
           | Ok () ->
-         (match Storage.open_database path with
+         (match startup_timed dependencies "storage_open" (fun () -> Storage.open_database path) with
           | Error error -> Error (Types.Restore_failed (Storage.diagnostic_error ~operation:"attachGraph" error))
           | Ok connection ->
             let callbacks = Storage.connection_callbacks connection in
@@ -5972,7 +5912,7 @@ let open_owned ~sw dependencies inspection ~graph_name ownership =
                     !installed_listener;
                   ignore (Storage.close callbacks)))
               (fun () ->
-                 match Storage.restore_database connection with
+                 match startup_timed dependencies "datascript_restore" (fun () -> Storage.restore_database connection) with
                  | Error error ->
                    Error (Types.Restore_failed (Storage.diagnostic_error ~operation:"attachGraph" error))
                  | Ok authoritative_database ->
@@ -6140,7 +6080,8 @@ let open_ ~sw dependencies inspection ~graph_name =
          in
          (match
             if generation_matches
-            then open_owned ~sw dependencies inspection ~graph_name ownership
+            then startup_timed dependencies "local_attach" (fun () ->
+              open_owned ~sw dependencies inspection ~graph_name ownership)
             else Error Types.Attachment_stale
           with
           | Ok _ as opened -> opened