mirror of
https://github.com/logseq/logseq.git
synced 2026-05-18 09:52:22 +00:00
enhance(cli): add --profile global option
This commit is contained in:
rcmerci
272
docs/agent-guide/068-logseq-cli-profile-timing.md
Normal file
272
docs/agent-guide/068-logseq-cli-profile-timing.md
Normal file
@@ -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:<method>` | `/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:<method>` 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:<method>` 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.
|
||||
|
||||
---
|
||||
@@ -232,6 +232,7 @@ Revision: <commit>
|
||||
Output formats:
|
||||
- Global `--output <human|json|edn>` 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:
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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)
|
||||
|
||||
@@ -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))))))
|
||||
|
||||
93
src/main/logseq/cli/profile.cljs
Normal file
93
src/main/logseq/cli/profile.cljs
Normal file
@@ -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))))
|
||||
@@ -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]
|
||||
|
||||
@@ -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]}]
|
||||
|
||||
@@ -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"
|
||||
|
||||
@@ -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"
|
||||
|
||||
@@ -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)))))))
|
||||
|
||||
62
src/test/logseq/cli/profile_test.cljs
Normal file
62
src/test/logseq/cli/profile_test.cljs
Normal file
@@ -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)))))))
|
||||
@@ -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")
|
||||
|
||||
@@ -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 [])
|
||||
|
||||
Reference in New Issue
Block a user