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..7a3278de --- /dev/null +++ b/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. 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..15e21ca7 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 @@ -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 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/App.swift b/swift/App.swift index 38be7647..5fce4002 100644 --- a/swift/App.swift +++ b/swift/App.swift @@ -1,3 +1,4 @@ +import Darwin import LUIAppleBackend import SwiftUI import OSLog @@ -5,13 +6,31 @@ import OSLog import AppKit #endif -@main struct JournalApplication: App { - @State private var platform = JournalApplicationPlatform(services: JournalNativeServices.makePlatformServices()) +@main enum JournalApplicationEntry { + @MainActor static func main() { + let entryTicks = mach_absolute_time() + JournalStartupDiagnostics.mark("main_enter") + JournalStartupDiagnostics.recordEntry(entryTicks) + 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/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..8fefad55 100644 --- a/swift/JournalRuntime.swift +++ b/swift/JournalRuntime.swift @@ -1,7 +1,48 @@ +import Darwin 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)") + } + + 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 + 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 +259,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 +284,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..10ec286f 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 @@ -186,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: @@ -211,7 +217,10 @@ 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) } do { setup = .success(try await prepare()) } catch { if !Task.isCancelled { setup = .failure(error) } } }