From 8989f98b51c957a9fc8589bbca17392286abd58f Mon Sep 17 00:00:00 2001 From: zy C Date: Sun, 8 Nov 2026 20:37:09 -0800 Subject: [PATCH 1/6] Coalesce startup catalog reconciliation and trace cached graph stages --- app/journal_graph_feed_plan.ml | 9 +++ docs/development/startup-diagnostics.md | 64 +++++++++++++++++++ .../lib/effect_runner/effect_runner.ml | 24 +++++-- logseq_overlay_db/lib/database.ml | 25 ++++++-- logseq_sync/lib/pure_reducer/core.ml | 25 ++++++-- logseq_sync/test/core_contract.ml | 53 +++++++++++++++ swift/JournalApplicationPlatform.swift | 1 + swift/JournalRuntime.swift | 52 ++++++++++++--- swift/JournalRuntimeHost.swift | 9 ++- 9 files changed, 240 insertions(+), 22 deletions(-) create mode 100644 docs/development/startup-diagnostics.md diff --git a/app/journal_graph_feed_plan.ml b/app/journal_graph_feed_plan.ml index f398580b..d532995a 100644 --- a/app/journal_graph_feed_plan.ml +++ b/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 diff --git a/docs/development/startup-diagnostics.md b/docs/development/startup-diagnostics.md new file mode 100644 index 00000000..ee4624f9 --- /dev/null +++ b/docs/development/startup-diagnostics.md @@ -0,0 +1,64 @@ +# Cached graph startup diagnostics + +Set `JOURNAL_STARTUP_DIAGNOSTICS=1` for a launched process to enable stage timing. +It is off by default; it does not enable networking, change 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 + +- 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. diff --git a/logseq_db_worker/lib/effect_runner/effect_runner.ml b/logseq_db_worker/lib/effect_runner/effect_runner.ml index bf44496a..17355fe1 100644 --- a/logseq_db_worker/lib/effect_runner/effect_runner.ml +++ b/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 diff --git a/logseq_overlay_db/lib/database.ml b/logseq_overlay_db/lib/database.ml index c36ac2f3..d32144f0 100644 --- a/logseq_overlay_db/lib/database.ml +++ b/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 @@ -5941,7 +5953,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 +5966,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 +5986,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 +6154,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 diff --git a/logseq_sync/lib/pure_reducer/core.ml b/logseq_sync/lib/pure_reducer/core.ml index ebfd6f08..361fd7a8 100644 --- a/logseq_sync/lib/pure_reducer/core.ml +++ b/logseq_sync/lib/pure_reducer/core.ml @@ -1502,8 +1502,16 @@ let request_catalog_reconciliation core = match core.user_id with | None -> unchanged core | Some user_id -> - let next, request = issue_request core (Fetch_catalog (account_scope core user_id)) in - { next; effects = [ publish next; Run request ] } + let account = account_scope core user_id in + let pending = List.exists (fun (Pending_effect ticket) -> + match ticket.kind with + | Fetch_catalog_kind -> ticket.scope = effect_scope_of_account account + | _ -> false) core.pending_effects in + if pending then + { next = { core with deferred_catalog_reconciliation = true }; effects = [ publish core ] } + else + let next, request = issue_request core (Fetch_catalog account) in + { next; effects = [ publish next; Run request ] } ;; let authenticate core user_id = @@ -2852,7 +2860,8 @@ let complete_runner : type a. t -> a effect_ticket -> a -> transition = match ticket.kind with | Load_catalog_kind -> complete_catalog_load core value | Save_catalog_kind -> deletion_selection_saved core - | Fetch_catalog_kind -> apply_fetched_catalog core value + | Fetch_catalog_kind -> + apply_fetched_catalog { core with deferred_catalog_reconciliation = false } value | Fetch_snapshot_baseline_kind -> (match decode_snapshot_baseline value, bootstrap_scope core.bootstrap with | Ok _, Some scope when graph_scope_is_current core scope -> @@ -2950,10 +2959,18 @@ let consume_completion core = function | Ok value -> complete_runner core ticket value | Error (Effect_failed message | Crypto_failed (_, message)) -> let source = message in - let message = match Logseq_db_types.Failure_diagnostic.decode source with + let diagnostic = Logseq_db_types.Failure_diagnostic.decode source in + let message = match diagnostic with | Some diagnostic -> Logseq_db_types.Failure_diagnostic.message diagnostic | None -> message in (match ticket.kind with + | Fetch_catalog_kind when core.deferred_catalog_reconciliation + && Option.exists (fun diagnostic -> Logseq_db_types.Failure_diagnostic.( + operation diagnostic = "httpTransport" && reason diagnostic = "cancelled")) diagnostic -> + (* Newer authentication can outlive a revoked shared token flight. *) + request_catalog_reconciliation core + | Fetch_catalog_kind -> + fail { core with deferred_catalog_reconciliation = false } During_catalog message | Save_catalog_kind -> (* Keep the existing advisory/deletion outcome. Only the safe diagnostics projection retains the producer's specific cause. *) diff --git a/logseq_sync/test/core_contract.ml b/logseq_sync/test/core_contract.ml index 885643b3..4e84b589 100644 --- a/logseq_sync/test/core_contract.ml +++ b/logseq_sync/test/core_contract.ml @@ -2278,6 +2278,55 @@ let authenticated_fetch user_id | _ -> Alcotest.fail "authentication did not issue one catalog request" ;; +let authentication_coalesces_pending_catalog () = + let authenticate core user = + Core.step core (Core.Account_authenticated { user_id = Some user }) + in + let catalog_requests effects = + List.filter + (function + | Core.Run (Core.Request (_, Core.Fetch_catalog _)) -> true + | _ -> false) + effects + |> List.length + in + let pending, ticket, _ = authenticated_fetch "user" in + let duplicate = authenticate pending.next "user" in + Alcotest.(check int) "same-scope authentication shares pending refresh" 0 + (catalog_requests duplicate.effects); + let cancelled = Logseq_db_types.Failure_diagnostic.( + create ~operation:"httpTransport" ~reason:"cancelled" () |> encode) in + let failed = Core.step duplicate.next + (Core.Runner_completed (Core.Completion (ticket, Error (Core.Effect_failed cancelled)))) in + Alcotest.(check int) "newer authentication survives a failed shared request" 1 + (catalog_requests failed.effects); + let retry_failure = List.find_map (function + | Core.Run (Core.Request (ticket, Core.Fetch_catalog _)) -> + Some (Core.Completion (ticket, Error (Core.Effect_failed "unavailable"))) + | _ -> None) failed.effects |> Option.get in + let exhausted = Core.step failed.next (Core.Runner_completed retry_failure) in + Alcotest.(check int) "shared authentication cannot retry indefinitely" 0 + (catalog_requests exhausted.effects); + Alcotest.(check bool) "retry failure remains visible" true + ((Core.state exhausted.next).snapshot.startup.failure = Some Core.During_catalog); + let rejected = Core.step duplicate.next + (Core.Runner_completed (Core.Completion (ticket, Error (Core.Effect_failed "invalid token")))) in + Alcotest.(check int) "ordinary authentication failures are not retried" 0 + (catalog_requests rejected.effects); + let completed = Core.step duplicate.next + (Core.Runner_completed (Core.Completion (ticket, Ok [graph]))) in + Alcotest.(check bool) "shared completion updates the catalog" true + ((Core.state completed.next).snapshot.catalog = [graph]); + Alcotest.(check int) "authentication can refresh after completion" 1 + (catalog_requests (authenticate completed.next "user").effects); + let resumed = Core.step pending.next + (Core.Foreground_changed { foreground = true; lifecycle_generation = 1L }) in + Alcotest.(check int) "old lifecycle cannot suppress current refresh" 1 + (catalog_requests (authenticate resumed.next "user").effects); + Alcotest.(check int) "another account owns a separate refresh" 1 + (catalog_requests (authenticate pending.next "other-user").effects) +;; + let account_deletion_completion signed_out (result : (unit, Core.effect_error) result) = List.find_map (function @@ -4260,6 +4309,10 @@ let scenarios = "authentication delegates catalog transport" `Quick authentication_delegates_catalog_transport + ; Alcotest.test_case + "authentication shares pending catalog refresh within its scope" + `Quick + authentication_coalesces_pending_catalog ; Alcotest.test_case "websocket connect uses the deployed graph path" `Quick diff --git a/swift/JournalApplicationPlatform.swift b/swift/JournalApplicationPlatform.swift index af983437..6c596924 100644 --- a/swift/JournalApplicationPlatform.swift +++ b/swift/JournalApplicationPlatform.swift @@ -144,6 +144,7 @@ import AppKit } let requestScope = startupScope failureScope = requestScope + if request == .timelinePresented { JournalStartupDiagnostics.mark("timeline_acknowledged") } requestObserver?(request) if request == .signOut { refresh?.cancel() diff --git a/swift/JournalRuntime.swift b/swift/JournalRuntime.swift index 6d7e2be6..80413235 100644 --- a/swift/JournalRuntime.swift +++ b/swift/JournalRuntime.swift @@ -2,6 +2,38 @@ import Foundation import LUIAppleBackend import Observation +@MainActor enum JournalStartupDiagnostics { + private static let enabled = ProcessInfo.processInfo.environment["JOURNAL_STARTUP_DIAGNOSTICS"] == "1" + + static func mark(_ stage: StaticString) { + guard enabled else { return } + write("stage=\(stage) phase=mark uptime_s=\(ProcessInfo.processInfo.systemUptime)") + } + + @discardableResult static func begin(_ stage: StaticString) -> TimeInterval? { + guard enabled else { return nil } + let now = ProcessInfo.processInfo.systemUptime + write("stage=\(stage) phase=begin uptime_s=\(now)") + return now + } + + static func end(_ stage: StaticString, since began: TimeInterval?) { + guard let began else { return } + let now = ProcessInfo.processInfo.systemUptime + write("stage=\(stage) phase=end uptime_s=\(now) elapsed_ms=\((now - began) * 1000)") + } + + static func measure(_ stage: StaticString, _ action: () throws -> Value) rethrows -> Value { + let began = begin(stage) + defer { end(stage, since: began) } + return try action() + } + + private static func write(_ fields: String) { + FileHandle.standardError.write(Data("journal-startup: source=swift \(fields)\n".utf8)) + } +} + /// C bridge entries exported by app/journal_lui_bridge.c (see also /// platform/native/lui_ocaml_bridge.c in the lui repository). Every entry that /// produces a patch copies it into owned bytes and releases the OCaml runtime @@ -218,7 +250,9 @@ private let platformRequest: PlatformRequestCallback = { data, length in self.platform = platform self.startupPayload = startupPayload do { - backend = try LUIAppleBackend(appIcons: journalAppIcons, extensionRegistry: extensionRegistry) + backend = try JournalStartupDiagnostics.measure("backend_init") { + try LUIAppleBackend(appIcons: journalAppIcons, extensionRegistry: extensionRegistry) + } } catch { throw FailureDetail(operation:.start,reason:Self.safeReason(error)) } backend.onEvent = { [weak self] event in self?.handle(event) } } @@ -241,13 +275,15 @@ private let platformRequest: PlatformRequestCallback = { data, length in #else let operatingSystem: Int32 = 2 #endif - let accepted = startupPayload.withUnsafeBytes { bytes in - luiOCamlStart( - receivePatch, - operatingSystem, - 2, - bytes.baseAddress?.assumingMemoryBound(to: CChar.self), - Int32(bytes.count)) + let accepted = JournalStartupDiagnostics.measure("ocaml_start") { + startupPayload.withUnsafeBytes { bytes in + luiOCamlStart( + receivePatch, + operatingSystem, + 2, + bytes.baseAddress?.assumingMemoryBound(to: CChar.self), + Int32(bytes.count)) + } } guard generation == identity else { throw CancellationError() } guard accepted == 1 else { diff --git a/swift/JournalRuntimeHost.swift b/swift/JournalRuntimeHost.swift index c57e7eaa..09e0b558 100644 --- a/swift/JournalRuntimeHost.swift +++ b/swift/JournalRuntimeHost.swift @@ -41,6 +41,7 @@ struct JournalRuntimeHost: View { } } else if let runtime, let rootID = runtime.rootID { LUISwiftUIRoot(backend: runtime.backend, rootID: rootID) + .onAppear { JournalStartupDiagnostics.mark("root_appeared") } } else { JournalStartupLoadingSurface(loading: false, initial: true, active: true) } @@ -74,7 +75,11 @@ struct JournalRuntimeHost: View { startingRuntime = next do { try next.start() - try await next.waitForInitialPlatformRequests() + do { + let began = JournalStartupDiagnostics.begin("initial_platform_requests") + defer { JournalStartupDiagnostics.end("initial_platform_requests", since: began) } + try await next.waitForInitialPlatformRequests() + } try Task.checkCancellation() guard startingRuntime === next else { throw CancellationError() } runtime = next @@ -212,6 +217,8 @@ struct JournalHost: View { .environment(\.journalStartupClock, clock) .task { guard setup == nil else { return } + let began = JournalStartupDiagnostics.begin("host_prepare") + defer { JournalStartupDiagnostics.end("host_prepare", since: began) } do { setup = .success(try await prepare()) } catch { if !Task.isCancelled { setup = .failure(error) } } } From 4a69d2ad4cd1d85df4ab501c1b5636cd83acbd3b Mon Sep 17 00:00:00 2001 From: zy C Date: Sun, 8 Nov 2026 21:15:52 -0800 Subject: [PATCH 2/6] Trace main entry and SwiftUI startup boundaries --- docs/development/startup-diagnostics.md | 8 ++++++++ swift/App.swift | 20 ++++++++++++++++++-- swift/JournalRuntimeHost.swift | 2 ++ 3 files changed, 28 insertions(+), 2 deletions(-) diff --git a/docs/development/startup-diagnostics.md b/docs/development/startup-diagnostics.md index ee4624f9..a724edaa 100644 --- a/docs/development/startup-diagnostics.md +++ b/docs/development/startup-diagnostics.md @@ -50,6 +50,14 @@ can contain private metadata; review and redact raw logs before sharing them. ## Interpretation +- `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 diff --git a/swift/App.swift b/swift/App.swift index 38be7647..99371faa 100644 --- a/swift/App.swift +++ b/swift/App.swift @@ -5,13 +5,29 @@ import OSLog import AppKit #endif -@main struct JournalApplication: App { - @State private var platform = JournalApplicationPlatform(services: JournalNativeServices.makePlatformServices()) +@main enum JournalApplicationEntry { + @MainActor static func main() { + JournalStartupDiagnostics.mark("main_enter") + JournalApplication.main() + } +} + +struct JournalApplication: App { + @State private var platform: JournalApplicationPlatform #if os(macOS) @NSApplicationDelegateAdaptor(JournalApplicationDelegate.self) private var delegate #endif + init() { + let began = JournalStartupDiagnostics.begin("app_init") + defer { JournalStartupDiagnostics.end("app_init", since: began) } + _platform = State(initialValue: JournalStartupDiagnostics.measure("native_services") { + JournalApplicationPlatform(services: JournalNativeServices.makePlatformServices()) + }) + } + var body: some Scene { + let _ = JournalStartupDiagnostics.mark("app_body") #if os(macOS) Window("Logseq Journal", id: "journal") { JournalHost(platform: platform, prepare: { diff --git a/swift/JournalRuntimeHost.swift b/swift/JournalRuntimeHost.swift index 09e0b558..10ec286f 100644 --- a/swift/JournalRuntimeHost.swift +++ b/swift/JournalRuntimeHost.swift @@ -191,6 +191,7 @@ struct JournalHost: View { @State private var clock = JournalStartupClock() var body: some View { + let _ = JournalStartupDiagnostics.mark("host_body") Group { switch setup { case .none: @@ -216,6 +217,7 @@ struct JournalHost: View { } .environment(\.journalStartupClock, clock) .task { + JournalStartupDiagnostics.mark("host_task_entered") guard setup == nil else { return } let began = JournalStartupDiagnostics.begin("host_prepare") defer { JournalStartupDiagnostics.end("host_prepare", since: began) } From eefb2d66415c27f517657b82175f07c3488d26a1 Mon Sep 17 00:00:00 2001 From: zy C Date: Mon, 9 Nov 2026 03:09:21 -0800 Subject: [PATCH 3/6] Capture raw main-entry ticks before diagnostic initialization --- swift/App.swift | 3 +++ swift/JournalRuntime.swift | 9 +++++++++ 2 files changed, 12 insertions(+) diff --git a/swift/App.swift b/swift/App.swift index 99371faa..5fce4002 100644 --- a/swift/App.swift +++ b/swift/App.swift @@ -1,3 +1,4 @@ +import Darwin import LUIAppleBackend import SwiftUI import OSLog @@ -7,7 +8,9 @@ import AppKit @main enum JournalApplicationEntry { @MainActor static func main() { + let entryTicks = mach_absolute_time() JournalStartupDiagnostics.mark("main_enter") + JournalStartupDiagnostics.recordEntry(entryTicks) JournalApplication.main() } } diff --git a/swift/JournalRuntime.swift b/swift/JournalRuntime.swift index 80413235..8fefad55 100644 --- a/swift/JournalRuntime.swift +++ b/swift/JournalRuntime.swift @@ -1,3 +1,4 @@ +import Darwin import Foundation import LUIAppleBackend import Observation @@ -10,6 +11,14 @@ import Observation write("stage=\(stage) phase=mark uptime_s=\(ProcessInfo.processInfo.systemUptime)") } + static func recordEntry(_ ticks: UInt64) { + guard enabled else { return } + var timebase = mach_timebase_info_data_t() + guard mach_timebase_info(&timebase) == KERN_SUCCESS else { return } + let uptime = Double(ticks) * Double(timebase.numer) / Double(timebase.denom) / 1_000_000_000 + write("stage=main_raw phase=mark uptime_s=\(uptime) mach_ticks=\(ticks)") + } + @discardableResult static func begin(_ stage: StaticString) -> TimeInterval? { guard enabled else { return nil } let now = ProcessInfo.processInfo.systemUptime From 0e39bfae998db949d7706bcaed8047ddf574f831 Mon Sep 17 00:00:00 2001 From: zy C Date: Mon, 9 Nov 2026 03:12:07 -0800 Subject: [PATCH 4/6] Hydrate only selected children without rebuilding the ident index --- logseq_overlay_db/lib/database.ml | 94 ++++--------------------------- 1 file changed, 10 insertions(+), 84 deletions(-) diff --git a/logseq_overlay_db/lib/database.ml b/logseq_overlay_db/lib/database.ml index d32144f0..15e21ca7 100644 --- a/logseq_overlay_db/lib/database.ml +++ b/logseq_overlay_db/lib/database.ml @@ -1769,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 @@ -3308,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 @@ -3322,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) ;; @@ -4377,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 @@ -4396,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 From 011113ab5e69762c12233e2664379af0e0914915 Mon Sep 17 00:00:00 2001 From: zy C Date: Mon, 9 Nov 2026 03:14:05 -0800 Subject: [PATCH 5/6] Publish a smaller first root prefix while retaining sealed read budgets --- app/journal_graph_feed_plan.ml | 10 ++++++++-- docs/development/startup-diagnostics.md | 10 ++++++++-- 2 files changed, 16 insertions(+), 4 deletions(-) diff --git a/app/journal_graph_feed_plan.ml b/app/journal_graph_feed_plan.ml index d532995a..c835e04c 100644 --- a/app/journal_graph_feed_plan.ml +++ b/app/journal_graph_feed_plan.ml @@ -766,14 +766,20 @@ let receive_root_tree t ~ports ~origin ~cached batch items next_cursor = with | Error message -> root_failure batch message | Ok projected -> - let selected = List.take batch.root_limit projected.entries in + let limit = + match batch.root_owner with + | Feed_roots scan when scan.root_publish_partial && Rrbvec.is_empty scan.root_days -> + min 4 batch.root_limit + | Feed_roots _ | Changed_roots _ -> batch.root_limit + in + let selected = List.take limit projected.entries in let ids = List.map (fun (entry : Projection.timeline_entry) -> Journal_model.id entry.block) selected in let cut = - if List.length projected.entries <= batch.root_limit + if List.length projected.entries <= limit then Rrbvec.length items else ( let last = List.hd (List.rev ids) in diff --git a/docs/development/startup-diagnostics.md b/docs/development/startup-diagnostics.md index a724edaa..7a3278de 100644 --- a/docs/development/startup-diagnostics.md +++ b/docs/development/startup-diagnostics.md @@ -1,8 +1,9 @@ # Cached graph startup diagnostics Set `JOURNAL_STARTUP_DIAGNOSTICS=1` for a launched process to enable stage timing. -It is off by default; it does not enable networking, change startup ordering, or -write graph data. With an already installed app on an explicitly selected iOS +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 @@ -50,6 +51,11 @@ 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. From 0a684de472337353722de58813c8ab0c7508d63d Mon Sep 17 00:00:00 2001 From: zy C Date: Mon, 9 Nov 2026 03:17:39 -0800 Subject: [PATCH 6/6] Keep existing first-prefix semantics after smaller-prefix regressions --- app/journal_graph_feed_plan.ml | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/app/journal_graph_feed_plan.ml b/app/journal_graph_feed_plan.ml index c835e04c..d532995a 100644 --- a/app/journal_graph_feed_plan.ml +++ b/app/journal_graph_feed_plan.ml @@ -766,20 +766,14 @@ let receive_root_tree t ~ports ~origin ~cached batch items next_cursor = with | Error message -> root_failure batch message | Ok projected -> - let limit = - match batch.root_owner with - | Feed_roots scan when scan.root_publish_partial && Rrbvec.is_empty scan.root_days -> - min 4 batch.root_limit - | Feed_roots _ | Changed_roots _ -> batch.root_limit - in - let selected = List.take limit projected.entries in + let selected = List.take batch.root_limit projected.entries in let ids = List.map (fun (entry : Projection.timeline_entry) -> Journal_model.id entry.block) selected in let cut = - if List.length projected.entries <= limit + if List.length projected.entries <= batch.root_limit then Rrbvec.length items else ( let last = List.hd (List.rev ids) in