diff --git a/docs/agent-guide/068-logseq-cli-profile-timing.md b/docs/agent-guide/068-logseq-cli-profile-timing.md new file mode 100644 index 0000000000..68441d6fd6 --- /dev/null +++ b/docs/agent-guide/068-logseq-cli-profile-timing.md @@ -0,0 +1,272 @@ +# Logseq CLI Profile Stage Timing Implementation Plan + +Goal: Add a global `--profile` option with default `false` so every `logseq` command can print stage-by-stage elapsed time without breaking existing command output contracts. + +Architecture: Introduce a lightweight profiling session in `logseq-cli` that records ordered stage spans across argument parsing, config resolution, command execution, server orchestration, and transport calls. +Architecture: Reuse existing `logseq-cli -> db-worker-node` boundaries by instrumenting `logseq.cli.main`, `logseq.cli.server`, and `logseq.cli.transport` rather than changing db-worker-node API contracts. +Architecture: Emit profile report lines to stderr only so stdout remains identical for human, JSON, and EDN command outputs. + +Tech Stack: ClojureScript, `promesa`, `babashka.cli`, `lambdaisland.glogi`, Node.js process I/O, existing `logseq-cli` and `db-worker-node` runtime boundaries. + +Related: Builds on `docs/agent-guide/003-db-worker-node-cli-orchestration.md`, `docs/agent-guide/005-logseq-cli-output-and-db-worker-node-log.md`, and `docs/agent-guide/028-logseq-cli-verbose-debug.md`. + +## Problem statement + +`logseq-cli` currently has debug logging via `--verbose`, but it does not provide a stable per-stage timing summary for each command run. + +Developers can see individual transport elapsed logs in debug mode, but they cannot reliably answer where command time is spent end to end. + +This is especially painful for commands that include daemon startup, lock waiting, readiness checks, and multiple thread-api invocations. + +The feature request is to add a global `--profile` option with default `false` and print stage timing for command execution. + +The new behavior must avoid changing functional command results and must not pollute stdout machine output. + +## Current implementation baseline + +Global CLI options are defined in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/command/core.cljs` via `global-spec*` and `parse-leading-global-opts`. + +Command runtime orchestration is centralized in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` in `run!`. + +Action dispatch and pre-checks are centralized in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/commands.cljs` in `execute`. + +Daemon lifecycle orchestration is centralized in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` with `ensure-server-started!` and helpers delegated to `logseq.db-worker.daemon`. + +Transport round trips are centralized in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/transport.cljs` in `invoke`. + +db-worker-node daemon CLI parsing lives in `/Users/rcmerci/gh-repos/logseq/src/main/frontend/worker/db_worker_node.cljs` and currently has no profile flag. + +## Target behavior + +`--profile` is a global option for `logseq` commands and defaults to `false` when absent. + +When `--profile` is enabled, command stdout content remains unchanged and profile output is written to stderr. + +Profile output includes total duration and ordered stage rows with elapsed milliseconds. + +Repeated stages such as multiple `transport/invoke` calls are aggregated by stage key with count, total, and average durations. + +A failed command still prints profile data for stages that ran before the failure. + +Help and version paths also support profiling and print minimal stage reports. + +No db-worker-node HTTP endpoint or thread-api signature changes are required. + +### Proposed stage taxonomy + +| Stage key | Source file | Trigger | +| --- | --- | --- | +| `cli.parse-args` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `commands/parse-args` call. | +| `cli.resolve-config` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `config/resolve-config` call. | +| `cli.ensure-data-dir` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `data-dir/ensure-data-dir!` call. | +| `cli.build-action` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `commands/build-action` call. | +| `cli.execute-action` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `commands/execute` call. | +| `server.ensure-started` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` | `ensure-server-started!` total path. | +| `server.spawn-daemon` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` | daemon spawn branch only. | +| `server.wait-lock` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` | wait for lock file and bound port. | +| `server.wait-ready` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` | wait for `/readyz`. | +| `transport.invoke:` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/transport.cljs` | per thread-api HTTP invoke. | +| `cli.format-result` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | `format/format-result` call. | +| `cli.total` | `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | whole `run!` lifecycle. | + +### Proposed stderr output example + +```text +[profile] total=842ms command=graph-info status=ok +[profile] cli.parse-args count=1 total=2ms avg=2ms +[profile] cli.resolve-config count=1 total=1ms avg=1ms +[profile] cli.ensure-data-dir count=1 total=3ms avg=3ms +[profile] cli.build-action count=1 total=1ms avg=1ms +[profile] server.ensure-started count=1 total=522ms avg=522ms +[profile] server.wait-ready count=1 total=417ms avg=417ms +[profile] transport.invoke:thread-api/q count=2 total=286ms avg=143ms +[profile] cli.format-result count=1 total=2ms avg=2ms +``` + +## Scope and non-goals + +In scope is a global `--profile` option for `logseq` command execution profiling. + +In scope is timing visibility for CLI orchestration stages and transport boundaries that dominate latency. + +In scope is deterministic stderr profile output suitable for local debugging and CI logs. + +Out of scope is changing db-worker-node protocol payloads or introducing profile fields into command data output. + +Out of scope is a full distributed trace system across child processes. + +Out of scope is changing default command behavior when `--profile` is not provided. + +## Testing Plan + +I will follow `@test-driven-development` and write failing tests before implementation. + +I will add a parser test in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/commands_test.cljs` that asserts `--profile` is accepted as a global option and is absent by default. + +I will add completion metadata tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/completion_generator_test.cljs` to verify `--profile` appears in generated zsh and bash completions. + +I will add runtime profiling tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/main_test.cljs` that assert profile lines are produced only when `--profile` is enabled. + +I will add transport profiling tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/transport_test.cljs` that assert `transport.invoke:` stage records include elapsed timing and aggregation counts. + +I will add server lifecycle profiling tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/server_test.cljs` that verify spawn and wait stages are recorded in profile-enabled runs. + +I will add a regression test in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/integration_test.cljs` confirming stdout JSON remains parseable and profile lines only appear on stderr. + +I will update docs assertions or snapshots only where global option text changes. + +NOTE: I will write *all* tests before I add any implementation behavior. + +## Architecture sketch + +```text +raw argv + -> cli.main/run! + -> profile session (enabled by --profile) + -> parse args + -> resolve config + -> ensure data dir + -> build action + -> execute action + -> cli.server ensure/start/reuse db-worker-node + -> cli.transport invoke thread-api methods + -> format result + -> stdout (unchanged command output) + -> stderr (profile summary when enabled) +``` + +## Implementation plan + +1. Read `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/command/core.cljs` and add `:profile` to `global-spec*` as boolean global option with help text. + +2. Add a RED test in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/commands_test.cljs` proving `commands/parse-args` accepts `--profile` and stores it under `:options`. + +3. Run the focused parser test and confirm it fails for the expected missing-option reason. + +4. Add RED completion tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/completion_generator_test.cljs` asserting generated completion scripts include `--profile`. + +5. Run focused completion tests and confirm failure before implementation. + +6. Create `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/profile.cljs` with a small profiling session API for span recording, aggregation, and stderr rendering. + +7. Add RED unit tests for the new profiling helper in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/log_test.cljs` or a new `profile_test.cljs` namespace. + +8. Run focused profiling helper tests and confirm failure before implementation. + +9. Instrument `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` to create a profiling session when `--profile` is present and wrap top-level stages. + +10. Extend `run!` return shape to include profile report lines or profile metadata in a non-breaking internal field consumed by `main`. + +11. Update `main` in `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` to print profile lines to stderr after command output handling. + +12. Add RED main runtime tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/main_test.cljs` for both enabled and disabled profile modes. + +13. Run focused main tests and confirm they fail before instrumentation is complete. + +14. Instrument `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` stage boundaries for ensure, spawn, wait-lock, and wait-ready using the shared profiling session in config. + +15. Add RED server profiling tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/server_test.cljs` to validate stage records for spawn and reuse paths. + +16. Run focused server tests and confirm expected failing assertions. + +17. Instrument `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/transport.cljs` so each invoke records `transport.invoke:` spans. + +18. Add RED transport profiling tests in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/transport_test.cljs` verifying stage key naming and aggregation semantics. + +19. Run focused transport tests and confirm failure before final implementation pass. + +20. Wire profile context propagation through the existing config flow without changing command action schemas. + +21. Add integration coverage in `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/integration_test.cljs` to verify stdout contract safety with `--output json` plus `--profile`. + +22. Run focused integration tests and confirm profile output is stderr-only. + +23. Update `/Users/rcmerci/gh-repos/logseq/docs/cli/logseq-cli.md` with a concise `--profile` section including output stream and stability notes. + +24. Run `bb dev:test -v logseq.cli.main-test`, `bb dev:test -v logseq.cli.transport-test`, and `bb dev:test -v logseq.cli.server-test`. + +25. Run `bb dev:test -v logseq.cli.integration-test` and verify machine-output regression safety. + +26. Run `bb dev:lint-and-test` for final regression. + +## File-by-file change map + +| File | Change | +| --- | --- | +| `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/command/core.cljs` | Add `:profile` global option metadata. | +| `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/profile.cljs` | Add profile session lifecycle, span recording, aggregation, and render helpers. | +| `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/main.cljs` | Create profile session, wrap top-level stages, and print stderr report. | +| `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/server.cljs` | Record daemon lifecycle stage timings for ensure/spawn/wait phases. | +| `/Users/rcmerci/gh-repos/logseq/src/main/logseq/cli/transport.cljs` | Record per-method invoke stage timings. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/commands_test.cljs` | Add parse coverage for `--profile`. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/completion_generator_test.cljs` | Add completion coverage for new global option. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/main_test.cljs` | Add runtime profile-on and profile-off behavior tests. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/server_test.cljs` | Add stage timing coverage for daemon orchestration paths. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/transport_test.cljs` | Add invoke stage timing and aggregation tests. | +| `/Users/rcmerci/gh-repos/logseq/src/test/logseq/cli/integration_test.cljs` | Assert stdout stability with profile enabled. | +| `/Users/rcmerci/gh-repos/logseq/docs/cli/logseq-cli.md` | Document `--profile` behavior and stderr output contract. | + +## Verification commands + +| Command | Expected result | +| --- | --- | +| `bb dev:test -v logseq.cli.commands-test` | Global option parse tests including `--profile` pass. | +| `bb dev:test -v logseq.cli.completion-generator-test` | Completion output includes `--profile` for zsh and bash. | +| `bb dev:test -v logseq.cli.main-test` | Profile output appears only when enabled. | +| `bb dev:test -v logseq.cli.transport-test` | Per-method transport stage timing tests pass. | +| `bb dev:test -v logseq.cli.server-test` | Daemon lifecycle stage profiling tests pass. | +| `bb dev:test -v logseq.cli.integration-test` | Structured stdout contract remains stable with profiling enabled. | +| `bb dev:lint-and-test` | Full lint and test suite remains green. | + +## Edge cases + +`--profile` combined with `--output json` or `--output edn` must not inject profile text into stdout. + +Commands that return early, such as `--help` and `--version`, should still produce valid and short profile reports when enabled. + +Commands failing during parse, config, or daemon startup should report only completed stages and not crash profile rendering. + +Commands with many thread-api calls, such as `show` and `sync download`, should aggregate repeated stage keys to avoid huge stderr output. + +Timing collection must remain low overhead when enabled and near-zero overhead when disabled. + +Concurrent async calls should keep deterministic aggregation and avoid data races in shared profile state. + +Detached daemon startup should still be represented from the CLI perspective even though child-process internals are not directly traced. + +## Rollout and compatibility notes + +This feature is opt-in and does not change default output behavior. + +Profile report output in this scope is human-readable text only. + +Stage key names are internal debug labels and are not a semver-stable public contract. + +If users request machine-parseable profile output later, add a follow-up `--profile-format` option instead of changing this first version. + +## Testing Details + +Behavioral coverage focuses on whether users can observe stage timing only when `--profile` is enabled and whether normal command output remains untouched. + +Integration tests must validate real command execution paths through server orchestration and transport boundaries, not only helper mocks. + +The most critical regression check is stdout purity for machine outputs while profiling data is emitted to stderr. + +## Implementation Details + +- Keep profile output stderr-only. +- Add `--profile` to global option parsing and completion metadata. +- Introduce a dedicated profile helper namespace instead of spreading ad hoc timing atoms. +- Pass profile session through config to avoid broad action schema changes. +- Instrument top-level `run!` stages in `main.cljs`. +- Instrument db-worker lifecycle boundaries in `server.cljs`. +- Instrument per-method invoke timing in `transport.cljs`. +- Aggregate repeated stage keys with count, total, and average. +- Preserve all existing command result formatting behavior. +- Document option behavior in CLI docs. + +## Question + +None. + +--- diff --git a/docs/cli/logseq-cli.md b/docs/cli/logseq-cli.md index 7330fb8860..e3a3dc9df9 100644 --- a/docs/cli/logseq-cli.md +++ b/docs/cli/logseq-cli.md @@ -232,6 +232,7 @@ Revision: Output formats: - Global `--output ` applies to all commands - Output formatting is controlled via global `--output`, `:output-format` in config, or `LOGSEQ_CLI_OUTPUT`. +- Global `--profile` enables stage timing output to **stderr**. This is for debugging latency and does not change command stdout payloads. - Human output is plain text. List/search commands render tables with a final `Count: N` line. For list and search subcommands, the ID column uses `:db/id` (not UUID). If `:db/ident` exists, an `IDENT` column is included. `list property` includes dedicated `TYPE` and `CARDINALITY` columns. Search table columns are `ID` and `TITLE`. Block titles can include multiple lines; multi-line rows align additional lines under the `TITLE` column. Times such as list `UPDATED-AT`/`CREATED-AT` and `graph info` `Created at` are shown in human-friendly relative form. Errors include error codes and may include a `Hint:` line. Use `--output json|edn` for structured output. - `sync download` progress lines are streamed to stdout only when progress is enabled. In `json`/`edn` mode, progress is disabled by default unless `--progress true` is provided. - JSON machine output preserves namespaced keyword semantics: diff --git a/src/main/logseq/cli/command/core.cljs b/src/main/logseq/cli/command/core.cljs index 1e95bb12dd..dc9f75ac9d 100644 --- a/src/main/logseq/cli/command/core.cljs +++ b/src/main/logseq/cli/command/core.cljs @@ -26,6 +26,8 @@ :validate #{"human" "json" "edn"}} :verbose {:desc "Enable verbose debug logging to stderr" :alias :v + :coerce :boolean} + :profile {:desc "Enable stage timing profile output to stderr" :coerce :boolean}}) (defn global-spec diff --git a/src/main/logseq/cli/completion_generator.cljs b/src/main/logseq/cli/completion_generator.cljs index 987456ad0d..7725ab8cb8 100644 --- a/src/main/logseq/cli/completion_generator.cljs +++ b/src/main/logseq/cli/completion_generator.cljs @@ -412,7 +412,7 @@ _logseq_multi_values() { (let [groups (extract-groups table) global-spec (-> table first :spec (select-keys [:help :version :config :graph :data-dir - :timeout-ms :output :verbose])) + :timeout-ms :output :verbose :profile])) global-keys (set (keys global-spec)) ;; Collect group names that have subcommands (dispatchers own these) group-set (set (group-commands table)) @@ -639,7 +639,7 @@ _logseq_multi_values_bash() { (let [groups (extract-groups table) global-spec (-> table first :spec (select-keys [:help :version :config :graph :data-dir - :timeout-ms :output :verbose])) + :timeout-ms :output :verbose :profile])) global-str (bash-global-opts-string global-spec) ;; Build case branches branches @@ -869,7 +869,7 @@ _logseq_multi_values_bash() { [table] (let [global-spec (-> table first :spec (select-keys [:help :version :config :graph :data-dir - :timeout-ms :output :verbose])) + :timeout-ms :output :verbose :profile])) global-keys (set (keys global-spec)) ;; Find options with conflicting completions across commands varied-keys (find-varied-option-keys table global-keys) diff --git a/src/main/logseq/cli/main.cljs b/src/main/logseq/cli/main.cljs index 64a70a3926..be03d3ba86 100644 --- a/src/main/logseq/cli/main.cljs +++ b/src/main/logseq/cli/main.cljs @@ -6,6 +6,7 @@ [logseq.cli.data-dir :as data-dir] [logseq.cli.format :as format] [logseq.cli.log :as cli-log] + [logseq.cli.profile :as profile] [logseq.cli.version :as version] [lambdaisland.glogi :as log] [promesa.core :as p])) @@ -15,28 +16,68 @@ (or (:exit-code result) (if (= :error (:status result)) 1 0))) -(defn run! +(defn- profile-enabled-argv? + [args] + (boolean (some #{"--profile"} args))) + +(defn- profile-command + [parsed] + (cond + (:help? parsed) "help" + (keyword? (:command parsed)) (name (:command parsed)) + (string? (:command parsed)) (:command parsed) + :else "unknown")) + +(defn- attach-profile-lines + [profile-session parsed result] + (if profile-session + (assoc result + :profile-lines + (profile/render-lines + (profile/report profile-session + {:command (profile-command parsed) + :status (if (zero? (:exit-code result)) :ok :error)}))) + result)) + +(defn ^:large-vars/cleanup-todo run! ([args] (run! args {})) ([args _opts] - (let [parsed (commands/parse-args args)] + (let [profile-session (profile/create-session (profile-enabled-argv? args)) + parsed (profile/time! profile-session "cli.parse-args" + (fn [] + (commands/parse-args args)))] (cond (:help? parsed) - (p/resolved {:exit-code 0 - :output (:summary parsed)}) + (p/resolved + (attach-profile-lines profile-session parsed + {:exit-code 0 + :output (:summary parsed)})) (not (:ok? parsed)) - (p/resolved {:exit-code 1 - :output (format/format-result {:status :error - :error (:error parsed) - :command (:command parsed)} - {})}) + (p/resolved + (attach-profile-lines + profile-session + parsed + {:exit-code 1 + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result {:status :error + :error (:error parsed) + :command (:command parsed)} + {})))})) (= :version (:command parsed)) - (p/resolved {:exit-code 0 - :output (version/format-version)}) + (p/resolved + (attach-profile-lines profile-session parsed + {:exit-code 0 + :output (version/format-version)})) :else - (let [cfg (config/resolve-config (:options parsed))] + (let [cfg* (profile/time! profile-session "cli.resolve-config" + (fn [] + (config/resolve-config (:options parsed)))) + cfg (cond-> cfg* + profile-session (assoc :profile-session profile-session))] (cli-log/set-verbose! (:verbose cfg)) (log/debug :event :cli/parsed-options :command (:command parsed) @@ -50,23 +91,42 @@ [k (cli-log/truncate-preview v)]) (dissoc cfg :auth-token)))) (try - (let [cfg (assoc cfg :data-dir (data-dir/ensure-data-dir! (:data-dir cfg))) - action-result (commands/build-action parsed cfg)] + (let [cfg (assoc cfg + :data-dir + (profile/time! profile-session "cli.ensure-data-dir" + (fn [] + (data-dir/ensure-data-dir! (:data-dir cfg))))) + action-result (profile/time! profile-session "cli.build-action" + (fn [] + (commands/build-action parsed cfg)))] (if-not (:ok? action-result) - (p/resolved {:exit-code 1 - :output (format/format-result {:status :error - :error (:error action-result) - :command (:command parsed) - :context (select-keys (:options parsed) - [:repo :graph :page :block])} - cfg)}) - (-> (commands/execute (:action action-result) cfg) + (p/resolved + (attach-profile-lines + profile-session + parsed + {:exit-code 1 + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result {:status :error + :error (:error action-result) + :command (:command parsed) + :context (select-keys (:options parsed) + [:repo :graph :page :block])} + cfg)))})) + (-> (profile/time! profile-session "cli.execute-action" + (fn [] + (commands/execute (:action action-result) cfg))) (p/then (fn [result] (let [opts (cond-> cfg (:output-format result) (assoc :output-format (:output-format result)))] - {:exit-code (result->exit-code result) - :output (format/format-result result opts)}))) + (attach-profile-lines + profile-session + parsed + {:exit-code (result->exit-code result) + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result result opts)))})))) (p/catch (fn [error] (let [data (ex-data error) message (cond @@ -79,34 +139,57 @@ :else (str error))] (if (= :data-dir-permission (:code data)) - {:exit-code 1 - :output (format/format-result {:status :error - :error {:code :data-dir-permission - :message message - :path (:path data)}} - cfg)} - {:exit-code 1 - :output (format/format-result {:status :error - :error {:code (or (:code data) :exception) - :message message}} - cfg)}))))))) + (attach-profile-lines + profile-session + parsed + {:exit-code 1 + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result {:status :error + :error {:code :data-dir-permission + :message message + :path (:path data)}} + cfg)))}) + (attach-profile-lines + profile-session + parsed + {:exit-code 1 + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result {:status :error + :error {:code (or (:code data) :exception) + :message message}} + cfg)))})))))))) (catch :default error (let [data (ex-data error) message (or (.-message error) (str error))] (if (= :data-dir-permission (:code data)) - (p/resolved {:exit-code 1 - :output (format/format-result {:status :error - :error {:code :data-dir-permission - :message message - :path (:path data)}} - cfg)}) + (p/resolved + (attach-profile-lines + profile-session + parsed + {:exit-code 1 + :output (profile/time! profile-session "cli.format-result" + (fn [] + (format/format-result {:status :error + :error {:code :data-dir-permission + :message message + :path (:path data)}} + cfg)))})) (throw error)))))))))) +(defn- print-profile-lines! + [profile-lines] + (doseq [line profile-lines] + (.write (.-stderr js/process) (str line "\n")))) + (defn main [& args] (-> (run! args) - (p/then (fn [{:keys [exit-code output]}] + (p/then (fn [{:keys [exit-code output profile-lines]}] (when (seq output) (println output)) + (when (seq profile-lines) + (print-profile-lines! profile-lines)) (when-not (zero? exit-code) (.exit js/process exit-code)))))) diff --git a/src/main/logseq/cli/profile.cljs b/src/main/logseq/cli/profile.cljs new file mode 100644 index 0000000000..deab83dd68 --- /dev/null +++ b/src/main/logseq/cli/profile.cljs @@ -0,0 +1,93 @@ +(ns logseq.cli.profile + "Stage timing profiler for logseq CLI runtime." + (:require [promesa.core :as p])) + +(defn create-session + [enabled?] + (when enabled? + {:enabled? true + :started-ms (js/Date.now) + :spans (atom [])})) + +(defn- record-span! + [session stage elapsed-ms] + (when session + (swap! (:spans session) conj {:stage stage + :elapsed-ms (max 0 elapsed-ms)}))) + +(defn- thenable? + [value] + (and (some? value) + (fn? (.-then value)))) + +(defn time! + [session stage f] + (if-not session + (f) + (let [start-ms (js/Date.now)] + (try + (let [result (f)] + (if (thenable? result) + (-> result + (p/finally (fn [] + (record-span! session stage (- (js/Date.now) start-ms))))) + (do + (record-span! session stage (- (js/Date.now) start-ms)) + result))) + (catch :default e + (record-span! session stage (- (js/Date.now) start-ms)) + (throw e)))))) + +(defn- summarize-stages + [spans] + (let [aggregated (reduce (fn [acc {:keys [stage elapsed-ms]}] + (update acc stage + (fn [{:keys [count total-ms] :as current}] + (if current + (assoc current + :count (inc count) + :total-ms (+ total-ms elapsed-ms)) + {:stage stage + :count 1 + :total-ms elapsed-ms})))) + {} + spans) + order (distinct (map :stage spans))] + (mapv (fn [stage] + (let [{:keys [count total-ms]} (get aggregated stage) + avg-ms (if (pos? count) + (js/Math.round (/ total-ms count)) + 0)] + {:stage stage + :count count + :total-ms total-ms + :avg-ms avg-ms})) + order))) + +(defn report + [session {:keys [command status]}] + (let [started-ms (or (:started-ms session) (js/Date.now)) + total-ms (max 0 (- (js/Date.now) started-ms)) + spans (vec (or @(some-> session :spans) [])) + spans (if (some #(= "cli.total" (:stage %)) spans) + spans + (conj spans {:stage "cli.total" + :elapsed-ms total-ms}))] + {:command command + :status status + :total-ms total-ms + :stages (summarize-stages spans)})) + +(defn render-lines + [{:keys [command status total-ms stages]}] + (let [status-str (if (keyword? status) (name status) (str status)) + header (str "[profile] total=" total-ms "ms" + " command=" command + " status=" status-str) + stage-lines (mapv (fn [{:keys [stage count total-ms avg-ms]}] + (str "[profile] " stage + " count=" count + " total=" total-ms "ms" + " avg=" avg-ms "ms")) + stages)] + (vec (cons header stage-lines)))) diff --git a/src/main/logseq/cli/server.cljs b/src/main/logseq/cli/server.cljs index d8baaa8c29..006c3087c0 100644 --- a/src/main/logseq/cli/server.cljs +++ b/src/main/logseq/cli/server.cljs @@ -9,6 +9,7 @@ [logseq.common.graph :as common-graph] [logseq.common.graph-dir :as graph-dir] [logseq.db-worker.daemon :as daemon] + [logseq.cli.profile :as profile] [promesa.core :as p])) (defn resolve-data-dir @@ -142,41 +143,53 @@ [config repo] (let [data-dir (resolve-data-dir config) path (lock-path data-dir repo) - requester-owner (requester-owner-source config)] - (ensure-repo-dir! data-dir repo) - (p/let [existing (read-lock path) - _ (cleanup-stale-lock! path existing) - _ (when (not (fs/existsSync path)) - (daemon/cleanup-orphan-processes! {:repo repo - :data-dir data-dir}) - (spawn-server! {:repo repo - :data-dir data-dir - :owner-source requester-owner - :create-empty-db? (:create-empty-db? config)}) - (-> (wait-for-lock path) - (p/catch (fn [e] - (if (= :timeout (:code (ex-data e))) - (let [orphans (daemon/find-orphan-processes {:repo repo - :data-dir data-dir}) - pids (mapv :pid orphans)] - (throw (ex-info "db-worker-node failed to create lock" - {:code :server-start-timeout-orphan - :repo repo - :pids pids}))) - (throw e)))))) - lock (read-lock path) - lock (if (and lock - (= :cli requester-owner) - (= :unknown (lock-owner-source lock))) - (rewrite-lock-owner-source! path lock :cli) - lock)] - (when-not lock - (throw (ex-info "db-worker-node failed to start" {:code :server-start-failed}))) - (p/let [_ (wait-for-ready lock)] - (let [lock-owner (lock-owner-source lock)] - (assoc lock - :owner-source lock-owner - :owned? (owner-manageable? requester-owner lock-owner))))))) + requester-owner (requester-owner-source config) + profile-session (:profile-session config)] + (profile/time! profile-session "server.ensure-started" + (fn [] + (ensure-repo-dir! data-dir repo) + (p/let [existing (read-lock path) + _ (cleanup-stale-lock! path existing) + _ (when (not (fs/existsSync path)) + (daemon/cleanup-orphan-processes! {:repo repo + :data-dir data-dir}) + (profile/time! profile-session + "server.spawn-daemon" + (fn [] + (spawn-server! {:repo repo + :data-dir data-dir + :owner-source requester-owner + :create-empty-db? (:create-empty-db? config)}))) + (-> (profile/time! profile-session + "server.wait-lock" + (fn [] + (wait-for-lock path))) + (p/catch (fn [e] + (if (= :timeout (:code (ex-data e))) + (let [orphans (daemon/find-orphan-processes {:repo repo + :data-dir data-dir}) + pids (mapv :pid orphans)] + (throw (ex-info "db-worker-node failed to create lock" + {:code :server-start-timeout-orphan + :repo repo + :pids pids}))) + (throw e)))))) + lock (read-lock path) + lock (if (and lock + (= :cli requester-owner) + (= :unknown (lock-owner-source lock))) + (rewrite-lock-owner-source! path lock :cli) + lock)] + (when-not lock + (throw (ex-info "db-worker-node failed to start" {:code :server-start-failed}))) + (p/let [_ (profile/time! profile-session + "server.wait-ready" + (fn [] + (wait-for-ready lock)))] + (let [lock-owner (lock-owner-source lock)] + (assoc lock + :owner-source lock-owner + :owned? (owner-manageable? requester-owner lock-owner))))))))) (defn ensure-server! [config repo] diff --git a/src/main/logseq/cli/transport.cljs b/src/main/logseq/cli/transport.cljs index 39a0186aff..49eb9f1bfa 100644 --- a/src/main/logseq/cli/transport.cljs +++ b/src/main/logseq/cli/transport.cljs @@ -7,6 +7,7 @@ [clojure.string :as string] [lambdaisland.glogi :as log] [logseq.cli.log :as cli-log] + [logseq.cli.profile :as profile] [logseq.db :as ldb] [promesa.core :as p])) @@ -88,7 +89,7 @@ :body body})))))) (defn invoke - [{:keys [base-url timeout-ms]} + [{:keys [base-url timeout-ms profile-session]} method direct-pass? args] (let [url (str (string/replace base-url #"/$" "") "/v1/invoke") method* (cond @@ -96,6 +97,7 @@ (string? method) method (nil? method) nil :else (str method)) + stage-key (str "transport.invoke:" method*) start-ms (js/Date.now) args-preview (cli-log/truncate-preview args) payload (if direct-pass? @@ -106,33 +108,35 @@ :directPass false :argsTransit (ldb/write-transit-str args)}) body (js/JSON.stringify (clj->js payload))] - (log/debug :event :cli.transport/invoke - :method method* - :direct-pass? direct-pass? - :args args-preview - :url url) - (p/let [{:keys [body]} (request {:method "POST" - :url url - :headers (base-headers) - :body body - :timeout-ms timeout-ms}) - {:keys [result resultTransit]} (js->clj (js/JSON.parse body) :keywordize-keys true)] - (if direct-pass? - (let [response-preview (cli-log/truncate-preview result)] - (log/debug :event :cli.transport/response - :method method* - :direct-pass? direct-pass? - :elapsed-ms (- (js/Date.now) start-ms) - :response response-preview) - result) - (let [decoded (ldb/read-transit-str resultTransit) - response-preview (cli-log/truncate-preview decoded)] - (log/debug :event :cli.transport/response - :method method* - :direct-pass? direct-pass? - :elapsed-ms (- (js/Date.now) start-ms) - :response response-preview) - decoded))))) + (profile/time! profile-session stage-key + (fn [] + (log/debug :event :cli.transport/invoke + :method method* + :direct-pass? direct-pass? + :args args-preview + :url url) + (p/let [{:keys [body]} (request {:method "POST" + :url url + :headers (base-headers) + :body body + :timeout-ms timeout-ms}) + {:keys [result resultTransit]} (js->clj (js/JSON.parse body) :keywordize-keys true)] + (if direct-pass? + (let [response-preview (cli-log/truncate-preview result)] + (log/debug :event :cli.transport/response + :method method* + :direct-pass? direct-pass? + :elapsed-ms (- (js/Date.now) start-ms) + :response response-preview) + result) + (let [decoded (ldb/read-transit-str resultTransit) + response-preview (cli-log/truncate-preview decoded)] + (log/debug :event :cli.transport/response + :method method* + :direct-pass? direct-pass? + :elapsed-ms (- (js/Date.now) start-ms) + :response response-preview) + decoded))))))) (defn- decode-event [{:keys [type payload]}] diff --git a/src/test/logseq/cli/commands_test.cljs b/src/test/logseq/cli/commands_test.cljs index 23cff60665..7c680963e1 100644 --- a/src/test/logseq/cli/commands_test.cljs +++ b/src/test/logseq/cli/commands_test.cljs @@ -415,7 +415,17 @@ (testing "global output option is accepted" (let [result (commands/parse-args ["--output" "json" "graph" "list"])] (is (true? (:ok? result))) - (is (= "json" (get-in result [:options :output])))))) + (is (= "json" (get-in result [:options :output]))))) + + (testing "global profile option defaults to absent" + (let [result (commands/parse-args ["graph" "list"])] + (is (true? (:ok? result))) + (is (nil? (get-in result [:options :profile]))))) + + (testing "global profile option is accepted as boolean flag" + (let [result (commands/parse-args ["--profile" "graph" "list"])] + (is (true? (:ok? result))) + (is (= true (get-in result [:options :profile])))))) (deftest test-parse-args-doctor (testing "doctor command parses" diff --git a/src/test/logseq/cli/completion_generator_test.cljs b/src/test/logseq/cli/completion_generator_test.cljs index 9001b1750e..2d08d3863b 100644 --- a/src/test/logseq/cli/completion_generator_test.cljs +++ b/src/test/logseq/cli/completion_generator_test.cljs @@ -37,7 +37,9 @@ (testing ":config has :complete :file" (is (= :file (get-in spec [:config :complete])))) (testing ":data-dir has :complete :dir" - (is (= :dir (get-in spec [:data-dir :complete])))))) + (is (= :dir (get-in spec [:data-dir :complete])))) + (testing ":profile is a global boolean flag" + (is (= :boolean (get-in spec [:profile :coerce])))))) (deftest test-list-spec-metadata (let [entries list-command/entries @@ -210,9 +212,12 @@ (is (string/includes? output "compdef _logseq logseq"))) (testing "boolean flags emit alias grouping" (is (string/includes? output "'{-v,--verbose}'["))) + (testing "global profile flag is present in zsh completion" + (is (string/includes? output "'--profile["))) (testing "global boolean flags do NOT emit --no- negation token" (is (not (string/includes? output "--no-verbose"))) - (is (not (string/includes? output "--no-help")))) + (is (not (string/includes? output "--no-help"))) + (is (not (string/includes? output "--no-profile")))) (testing "enum options emit separate long= and short+ specs" (is (string/includes? output "--output=[Output format. Default: human]:value:(edn human json)'")) (is (string/includes? output "-o[Output format. Default: human]:value:(edn human json)'"))) @@ -298,10 +303,12 @@ (is (string/includes? output "--type")) (is (string/includes? output "--file"))) (testing "boolean flags appear in wordlist" - (is (string/includes? output "--verbose"))) + (is (string/includes? output "--verbose")) + (is (string/includes? output "--profile"))) (testing "global boolean flags do NOT have --no- variants in wordlist" (is (not (string/includes? output "--no-verbose"))) - (is (not (string/includes? output "--no-help")))) + (is (not (string/includes? output "--no-help"))) + (is (not (string/includes? output "--no-profile")))) (testing "enum values use compgen -W" (is (re-find #"compgen -W.*edn human json" output))) (testing ":complete :file uses compgen -f" @@ -390,7 +397,7 @@ (deftest test-bash-find-varied-option-keys (let [global-spec (-> full-table first :spec (select-keys [:help :version :config :graph :data-dir - :timeout-ms :output :verbose])) + :timeout-ms :output :verbose :profile])) global-keys (set (keys global-spec)) varied (gen/find-varied-option-keys full-table global-keys)] (testing "--type is detected as varied" diff --git a/src/test/logseq/cli/main_test.cljs b/src/test/logseq/cli/main_test.cljs index 9ea8aa82d3..4ae5d9ee1e 100644 --- a/src/test/logseq/cli/main_test.cljs +++ b/src/test/logseq/cli/main_test.cljs @@ -2,6 +2,7 @@ (:require [cljs.test :refer [async deftest is]] [clojure.string :as string] [logseq.cli.main :as cli-main] + [logseq.cli.test-helper :as test-helper] [promesa.core :as p])) (deftest test-version-output @@ -31,3 +32,84 @@ (is (= 0 (result->exit-code {:status :ok}))) (is (= 1 (result->exit-code {:status :error}))) (is (= 7 (result->exit-code {:status :error :exit-code 7}))))) + +(deftest test-profile-output-enabled-for-version + (async done + (-> (p/let [result (cli-main/run! ["--profile" "--version"] {:exit? false}) + profile-lines (:profile-lines result)] + (is (= 0 (:exit-code result))) + (is (string/includes? (:output result) "Build time: test-build-time")) + (is (vector? profile-lines)) + (is (seq profile-lines)) + (when (seq profile-lines) + (is (string/starts-with? (first profile-lines) "[profile] total="))) + (is (some #(string/includes? % "cli.parse-args") profile-lines)) + (is (some #(string/includes? % "cli.total") profile-lines)) + (done)) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done)))))) + +(deftest test-profile-output-disabled-by-default + (async done + (-> (p/let [result (cli-main/run! ["--version"] {:exit? false})] + (is (= 0 (:exit-code result))) + (is (nil? (:profile-lines result))) + (done)) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done)))))) + +(deftest test-run-profile-lines-enabled + (async done + (-> (p/let [result (cli-main/run! ["--profile" "--help"] {:exit? false}) + lines (:profile-lines result)] + (is (= 0 (:exit-code result))) + (is (seq lines)) + (when (seq lines) + (is (string/starts-with? (first lines) "[profile] total="))) + (is (some #(string/includes? % "cli.parse-args count=1") lines)) + (is (some #(string/includes? % "cli.total count=1") lines)) + (done)) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done)))))) + +(deftest test-run-profile-lines-disabled + (async done + (-> (p/let [result (cli-main/run! ["--help"] {:exit? false})] + (is (= 0 (:exit-code result))) + (is (nil? (:profile-lines result))) + (done)) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done)))))) + +(deftest test-main-prints-profile-lines-to-stderr + (async done + (let [stderr-writes (atom []) + stdout-lines (atom [])] + (-> (test-helper/with-js-property-override + (.-stderr js/process) + "write" + (fn [text] + (swap! stderr-writes conj text) + true) + (fn [] + (p/with-redefs [cli-main/run! (fn [_args] + (p/resolved {:exit-code 0 + :output "ok-output" + :profile-lines ["[profile] total=1ms command=help status=ok" + "[profile] cli.total count=1 total=1ms avg=1ms"]})) + println (fn [& args] + (swap! stdout-lines conj (string/join " " args)))] + (cli-main/main "--profile" "--help")))) + (p/then (fn [_] + (let [stderr-text (apply str @stderr-writes)] + (is (= ["ok-output"] @stdout-lines)) + (is (string/includes? stderr-text "[profile] total=1ms command=help status=ok")) + (is (string/includes? stderr-text "[profile] cli.total count=1 total=1ms avg=1ms")) + (done)))) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done))))))) diff --git a/src/test/logseq/cli/profile_test.cljs b/src/test/logseq/cli/profile_test.cljs new file mode 100644 index 0000000000..9401d8244e --- /dev/null +++ b/src/test/logseq/cli/profile_test.cljs @@ -0,0 +1,62 @@ +(ns logseq.cli.profile-test + (:require [cljs.test :refer [async deftest is testing]] + [clojure.string :as string] + [logseq.cli.profile :as profile] + [promesa.core :as p])) + +(deftest test-create-session + (testing "disabled profile returns nil session" + (is (nil? (profile/create-session false)))) + + (testing "enabled profile returns session map" + (let [session (profile/create-session true)] + (is (map? session)) + (is (some? (:started-ms session)))))) + +(deftest test-report-aggregates-repeated-stages + (let [session (profile/create-session true)] + (profile/time! session "cli.parse-args" (fn [] :ok)) + (profile/time! session "cli.parse-args" (fn [] :ok)) + (profile/time! session "cli.build-action" (fn [] :ok)) + (let [report (profile/report session {:command "graph-list" :status :ok}) + by-stage (into {} (map (juxt :stage identity) (:stages report)))] + (is (number? (:total-ms report))) + (is (>= (:total-ms report) 0)) + (is (= "graph-list" (:command report))) + (is (= :ok (:status report))) + (is (= 2 (get-in by-stage ["cli.parse-args" :count]))) + (is (= 1 (get-in by-stage ["cli.build-action" :count]))) + (is (= 1 (get-in by-stage ["cli.total" :count])))))) + +(deftest test-time-records-stage-when-thunk-throws + (let [session (profile/create-session true)] + (try + (profile/time! session "cli.parse-args" (fn [] + (throw (ex-info "boom" {:code :boom})))) + (is false "expected exception") + (catch :default _ + (let [report (profile/report session {:command "graph-list" :status :error}) + by-stage (into {} (map (juxt :stage identity) (:stages report)))] + (is (= 1 (get-in by-stage ["cli.parse-args" :count])))))))) + +(deftest test-time-records-async-stage + (async done + (let [session (profile/create-session true)] + (-> (profile/time! session "transport.invoke:thread-api/q" + (fn [] + (p/delay 5 :ok))) + (p/then (fn [result] + (is (= :ok result)) + (let [report (profile/report session {:command "query" :status :ok}) + by-stage (into {} (map (juxt :stage identity) (:stages report)))] + (is (= 1 (get-in by-stage ["transport.invoke:thread-api/q" :count])))))) + (p/then (fn [_] + (let [lines (profile/render-lines (profile/report session {:command "query" :status :ok}))] + (is (seq lines)) + (when (seq lines) + (is (string/starts-with? (first lines) "[profile] total="))) + (is (some #(string/includes? % "transport.invoke:thread-api/q") lines)) + (done)))) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done))))))) diff --git a/src/test/logseq/cli/server_test.cljs b/src/test/logseq/cli/server_test.cljs index dc0a28476b..37f09fade2 100644 --- a/src/test/logseq/cli/server_test.cljs +++ b/src/test/logseq/cli/server_test.cljs @@ -6,6 +6,7 @@ ["path" :as node-path] [cljs.test :refer [async deftest is]] [frontend.test.node-helper :as node-helper] + [logseq.cli.profile :as profile] [logseq.cli.server :as cli-server] [logseq.cli.test-helper :as test-helper] [logseq.db-worker.daemon :as daemon] @@ -270,6 +271,41 @@ (is false (str "unexpected error: " e)))) (p/finally done))))) +(deftest ensure-server-records-profile-stages-on-spawn-path + (async done + (let [data-dir (node-helper/create-tmp-dir "cli-server-profile") + repo (str "logseq_db_profile_" (subs (str (random-uuid)) 0 8)) + session (profile/create-session true) + read-lock-calls (atom 0) + lock {:repo repo + :pid (.-pid js/process) + :host "127.0.0.1" + :port 9310 + :owner-source :cli}] + (-> (p/with-redefs [daemon/read-lock (fn [_] + (if (= 1 (swap! read-lock-calls inc)) + nil + lock)) + daemon/cleanup-stale-lock! (fn [_ _] (p/resolved nil)) + daemon/cleanup-orphan-processes! (fn [_] {:orphans [] :killed-pids []}) + daemon/spawn-server! (fn [_] nil) + daemon/wait-for-lock (fn [_] (p/resolved true)) + daemon/wait-for-ready (fn [_] (p/resolved true))] + (cli-server/ensure-server! {:data-dir data-dir + :profile-session session} + repo)) + (p/then (fn [_] + (let [report (profile/report session {:command "server-start" + :status :ok}) + by-stage (into {} (map (juxt :stage identity) (:stages report)))] + (is (= 1 (get-in by-stage ["server.ensure-started" :count]))) + (is (= 1 (get-in by-stage ["server.spawn-daemon" :count]))) + (is (= 1 (get-in by-stage ["server.wait-lock" :count]))) + (is (= 1 (get-in by-stage ["server.wait-ready" :count])))))) + (p/catch (fn [e] + (is false (str "unexpected error: " e)))) + (p/finally done))))) + (deftest list-servers-includes-revision-from-lock (async done (let [data-dir (node-helper/create-tmp-dir "cli-server-list-revision") diff --git a/src/test/logseq/cli/transport_test.cljs b/src/test/logseq/cli/transport_test.cljs index 59068a1b96..7172293c76 100644 --- a/src/test/logseq/cli/transport_test.cljs +++ b/src/test/logseq/cli/transport_test.cljs @@ -1,5 +1,6 @@ (ns logseq.cli.transport-test (:require [cljs.test :refer [deftest is async testing]] + [logseq.cli.profile :as profile] [logseq.cli.test-helper :as test-helper] [logseq.cli.transport :as transport] [logseq.db :as ldb] @@ -194,6 +195,34 @@ (is false (str "unexpected error: " e)) (done))))))) +(deftest test-invoke-records-profile-stage-and-aggregation + (async done + (let [session (profile/create-session true)] + (-> (p/let [{:keys [url stop!]} (start-server + (fn [_req ^js res] + (.writeHead res 200 #js {"Content-Type" "application/json"}) + (.end res (js/JSON.stringify #js {:result "ok"})))) + _ (transport/invoke {:base-url url + :profile-session session} + :thread-api/q + true + ["repo" [:block/title]]) + _ (transport/invoke {:base-url url + :profile-session session} + :thread-api/q + true + ["repo" [:block/title]]) + report (profile/report session {:command "query" + :status :ok}) + by-stage (into {} (map (juxt :stage identity) (:stages report)))] + (is (= 2 (get-in by-stage ["transport.invoke:thread-api/q" :count]))) + (is (pos? (get-in by-stage ["transport.invoke:thread-api/q" :total-ms]))) + (p/let [_ (stop!)] true)) + (p/then (fn [_] (done))) + (p/catch (fn [e] + (is false (str "unexpected error: " e)) + (done))))))) + (deftest test-connect-events-decodes-rtc-log-and-cleans-up (async done (let [received (atom [])