From ec4e31fa4b4123d7600fe741a4d5bab0a5da3f59 Mon Sep 17 00:00:00 2001 From: rcmerci Date: Tue, 31 Mar 2026 21:41:12 +0800 Subject: [PATCH] enhance(cli): update --profile output --- docs/cli/logseq-cli.md | 9 ++ src/main/logseq/cli/profile.cljs | 178 +++++++++++++++++++++++--- src/test/logseq/cli/main_test.cljs | 25 ++-- src/test/logseq/cli/profile_test.cljs | 111 +++++++++++++++- 4 files changed, 292 insertions(+), 31 deletions(-) diff --git a/docs/cli/logseq-cli.md b/docs/cli/logseq-cli.md index 9e008e943a..f79906be9b 100644 --- a/docs/cli/logseq-cli.md +++ b/docs/cli/logseq-cli.md @@ -250,6 +250,15 @@ 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 profile output is rendered as a tree (similar to `show` output style). The elapsed time column is printed at the far left with fixed width for alignment, for example: + ```text + 146ms command=list status=ok + stages + 146ms └── cli.total + 4ms ├── cli.parse-args + 139ms └── cli.execute-action + 129ms └── transport.invoke:thread-api/cli-list-pages + ``` - 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. - `example` human output includes `Selector`, `Matched commands`, and `Examples` sections. Structured output (`json`/`edn`) includes `selector`, `matched-commands`, `examples`, and `message` fields under `data`. - `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. diff --git a/src/main/logseq/cli/profile.cljs b/src/main/logseq/cli/profile.cljs index deab83dd68..6034b3d8f8 100644 --- a/src/main/logseq/cli/profile.cljs +++ b/src/main/logseq/cli/profile.cljs @@ -7,13 +7,24 @@ (when enabled? {:enabled? true :started-ms (js/Date.now) - :spans (atom [])})) + :spans (atom []) + :next-span-id (atom 0)})) + +(defn- next-span-id + [session] + (swap! (:next-span-id session) inc)) (defn- record-span! - [session stage elapsed-ms] + [session {:keys [stage span-id started-ms ended-ms]}] (when session - (swap! (:spans session) conj {:stage stage - :elapsed-ms (max 0 elapsed-ms)}))) + (let [started-ms (or started-ms ended-ms 0) + ended-ms (or ended-ms started-ms) + elapsed-ms (max 0 (- ended-ms started-ms))] + (swap! (:spans session) conj {:stage stage + :span-id span-id + :started-ms started-ms + :ended-ms ended-ms + :elapsed-ms elapsed-ms})))) (defn- thenable? [value] @@ -24,18 +35,28 @@ [session stage f] (if-not session (f) - (let [start-ms (js/Date.now)] + (let [start-ms (js/Date.now) + span-id (next-span-id session)] (try (let [result (f)] (if (thenable? result) (-> result (p/finally (fn [] - (record-span! session stage (- (js/Date.now) start-ms))))) + (record-span! session {:stage stage + :span-id span-id + :started-ms start-ms + :ended-ms (js/Date.now)})))) (do - (record-span! session stage (- (js/Date.now) start-ms)) + (record-span! session {:stage stage + :span-id span-id + :started-ms start-ms + :ended-ms (js/Date.now)}) result))) (catch :default e - (record-span! session stage (- (js/Date.now) start-ms)) + (record-span! session {:stage stage + :span-id span-id + :started-ms start-ms + :ended-ms (js/Date.now)}) (throw e)))))) (defn- summarize-stages @@ -67,27 +88,144 @@ (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)) + now-ms (js/Date.now) + total-ms (max 0 (- now-ms started-ms)) spans (vec (or @(some-> session :spans) [])) spans (if (some #(= "cli.total" (:stage %)) spans) spans (conj spans {:stage "cli.total" + :span-id 0 + :started-ms started-ms + :ended-ms now-ms :elapsed-ms total-ms}))] {:command command :status status :total-ms total-ms + :spans spans :stages (summarize-stages spans)})) +(defn- span-node + [span] + (let [elapsed-ms (max 0 (or (:elapsed-ms span) 0))] + {:label (:stage span) + :span span + :elapsed-ms elapsed-ms + :children (atom [])})) + +(defn- span-contains? + [outer inner] + (let [outer-start (:started-ms outer) + outer-end (:ended-ms outer) + inner-start (:started-ms inner) + inner-end (:ended-ms inner)] + (and (number? outer-start) + (number? outer-end) + (number? inner-start) + (number? inner-end) + (<= outer-start inner-start) + (>= outer-end inner-end)))) + +(defn- sort-spans-for-tree + [spans] + (sort-by (fn [{:keys [started-ms ended-ms span-id]}] + (let [start (or started-ms 0) + end (or ended-ms start) + duration (max 0 (- end start))] + [start (- duration) (or span-id 0)])) + spans)) + +(defn- freeze-node + [node] + (let [children @(:children node)] + (-> node + (dissoc :span) + (assoc :children (mapv freeze-node children))))) + +(defn- build-stage-tree-from-spans + [spans] + (let [ordered (sort-spans-for-tree spans) + roots (atom []) + stack (atom []) + trim-stack (fn [current-stack span] + (loop [items current-stack] + (if (and (seq items) + (not (span-contains? (:span (peek items)) span))) + (recur (pop items)) + items))) + push-node! (fn [parent child] + (if parent + (swap! (:children parent) conj child) + (swap! roots conj child)))] + (doseq [span ordered] + (let [node (span-node span) + trimmed (trim-stack @stack span) + parent (peek trimmed)] + (push-node! parent node) + (reset! stack (conj trimmed node)))) + {:label "stages" + :children (mapv freeze-node @roots)})) + +(defn- build-stage-tree-from-stages + [stages] + {:label "stages" + :children (mapv (fn [stage-data] + {:label (:stage stage-data) + :elapsed-ms (max 0 (or (:elapsed-ms stage-data) + (:total-ms stage-data) + 0)) + :children []}) + stages)}) + +(defn- stage-node->text + [{:keys [label]}] + label) + +(defn- render-stage-tree-rows + [stage-tree] + (let [rows (atom [{:elapsed-ms nil + :text (:label stage-tree)}]) + walk (fn walk [node prefix] + (let [children (:children node) + total (count children)] + (doseq [[idx child] (map-indexed vector children)] + (let [last-child? (= idx (dec total)) + branch (if last-child? "└── " "├── ") + next-prefix (str prefix (if last-child? " " "│ "))] + (swap! rows conj {:elapsed-ms (:elapsed-ms child) + :text (str prefix + branch + (stage-node->text child))}) + (walk child next-prefix)))))] + (walk stage-tree "") + @rows)) + +(defn- pad-right + [value width] + (let [padding (max 0 (- width (count value)))] + (str value (apply str (repeat padding " "))))) + +(defn- format-profile-lines + [rows] + (let [duration-strs (mapv (fn [{:keys [elapsed-ms]}] + (when (number? elapsed-ms) + (str elapsed-ms "ms"))) + rows) + duration-width (apply max 0 (map #(count (or % "")) duration-strs))] + (mapv (fn [{:keys [text]} duration-str] + (str (pad-right (or duration-str "") duration-width) + " " + text)) + rows + duration-strs))) + (defn render-lines - [{:keys [command status total-ms stages]}] + [{:keys [command status total-ms spans 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)))) + header-row {:elapsed-ms total-ms + :text (str "command=" command + " status=" status-str)} + stage-tree (if (seq spans) + (build-stage-tree-from-spans spans) + (build-stage-tree-from-stages stages)) + stage-rows (render-stage-tree-rows stage-tree)] + (format-profile-lines (vec (cons header-row stage-rows))))) \ No newline at end of file diff --git a/src/test/logseq/cli/main_test.cljs b/src/test/logseq/cli/main_test.cljs index 685c4b4a34..14d8a5e9c6 100644 --- a/src/test/logseq/cli/main_test.cljs +++ b/src/test/logseq/cli/main_test.cljs @@ -43,7 +43,8 @@ (is (vector? profile-lines)) (is (seq profile-lines)) (when (seq profile-lines) - (is (string/starts-with? (first profile-lines) "[profile] total="))) + (is (re-find #"^\d+ms command=version status=ok$" (first profile-lines)))) + (is (some #(= "stages" (string/trim %)) profile-lines)) (is (some #(string/includes? % "cli.parse-args") profile-lines)) (is (some #(string/includes? % "cli.total") profile-lines)) (done)) @@ -68,9 +69,12 @@ (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)) + (is (re-find #"^\d+ms command=help status=ok$" (first lines)))) + (is (some #(= "stages" (string/trim %)) lines)) + (is (some #(string/includes? % "cli.parse-args") lines)) + (is (some #(string/includes? % "cli.total") lines)) + (is (not-any? #(string/includes? % "[profile]") lines)) + (is (not-any? #(string/includes? % "count=") lines)) (done)) (p/catch (fn [e] (is false (str "unexpected error: " e)) @@ -100,16 +104,19 @@ (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"]})) + :profile-lines ["1ms command=help status=ok" + " stages" + "1ms └── cli" + "1ms └── cli.total"]})) 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")) + (is (string/includes? stderr-text "1ms command=help status=ok")) + (is (string/includes? stderr-text " stages")) + (is (string/includes? stderr-text "1ms └── cli.total")) (done)))) (p/catch (fn [e] (is false (str "unexpected error: " e)) @@ -127,4 +134,4 @@ (is (not (string/includes? (:output result) "at ")) "output should not contain a stack trace"))) (p/catch (fn [e] (is false (str "unexpected error: " e)))) - (p/finally (fn [] (done)))))) + (p/finally (fn [] (done)))))) \ No newline at end of file diff --git a/src/test/logseq/cli/profile_test.cljs b/src/test/logseq/cli/profile_test.cljs index 9401d8244e..7086534c29 100644 --- a/src/test/logseq/cli/profile_test.cljs +++ b/src/test/logseq/cli/profile_test.cljs @@ -39,6 +39,112 @@ by-stage (into {} (map (juxt :stage identity) (:stages report)))] (is (= 1 (get-in by-stage ["cli.parse-args" :count])))))))) +(deftest test-render-lines-renders-logical-containment-tree + (let [lines (profile/render-lines {:command "graph-list" + :status :ok + :total-ms 42 + :stages [] + :spans [{:stage "cli.total" + :elapsed-ms 42 + :started-ms 0 + :ended-ms 42 + :span-id 0} + {:stage "cli.parse-args" + :elapsed-ms 2 + :started-ms 1 + :ended-ms 3 + :span-id 1} + {:stage "cli.execute-action" + :elapsed-ms 30 + :started-ms 5 + :ended-ms 35 + :span-id 2} + {:stage "transport.invoke:thread-api/q" + :elapsed-ms 8 + :started-ms 12 + :ended-ms 20 + :span-id 3}]})] + (is (= "42ms command=graph-list status=ok" (first lines))) + (is (= "stages" (string/trim (second lines)))) + (is (some #(= "42ms └── cli.total" %) lines)) + (is (some #(string/includes? % "├── cli.parse-args") lines)) + (is (some #(string/includes? % "└── cli.execute-action") lines)) + (is (some #(string/includes? % "└── transport.invoke:thread-api/q") lines)) + (is (not-any? #(string/includes? % "[profile]") lines)) + (is (not-any? #(string/includes? % "count=") lines)) + (is (not-any? #(string/includes? % "avg=") lines)))) + +(deftest test-render-lines-uses-containment-not-stage-prefix + (let [lines (profile/render-lines {:command "query" + :status :ok + :total-ms 20 + :stages [] + :spans [{:stage "outer" + :elapsed-ms 20 + :started-ms 0 + :ended-ms 20 + :span-id 0} + {:stage "transport.invoke:thread-api/q" + :elapsed-ms 10 + :started-ms 5 + :ended-ms 15 + :span-id 1}]})] + (is (some #(= "20ms └── outer" %) lines)) + (is (some #(string/includes? % "└── transport.invoke:thread-api/q") lines)))) + +(deftest test-render-lines-does-not-merge-identical-stage-calls + (let [lines (profile/render-lines {:command "query" + :status :ok + :total-ms 30 + :stages [] + :spans [{:stage "outer" + :elapsed-ms 30 + :started-ms 0 + :ended-ms 30 + :span-id 0} + {:stage "transport.invoke:thread-api/q" + :elapsed-ms 5 + :started-ms 5 + :ended-ms 10 + :span-id 1} + {:stage "transport.invoke:thread-api/q" + :elapsed-ms 5 + :started-ms 15 + :ended-ms 20 + :span-id 2}]}) + q-lines (filter #(string/includes? % "transport.invoke:thread-api/q") lines)] + (is (= 2 (count q-lines))) + (is (= ["5ms ├── transport.invoke:thread-api/q" + "5ms └── transport.invoke:thread-api/q"] + (vec q-lines))))) + +(deftest test-render-lines-aligns-tree-column-for-different-durations + (let [lines (profile/render-lines {:command "query" + :status :ok + :total-ms 120 + :stages [] + :spans [{:stage "outer" + :elapsed-ms 120 + :started-ms 0 + :ended-ms 120 + :span-id 0} + {:stage "child.short" + :elapsed-ms 2 + :started-ms 5 + :ended-ms 7 + :span-id 1} + {:stage "child.long" + :elapsed-ms 45 + :started-ms 10 + :ended-ms 55 + :span-id 2}]}) + short-line (first (filter #(string/includes? % "child.short") lines)) + long-line (first (filter #(string/includes? % "child.long") lines))] + (is (some? short-line)) + (is (some? long-line)) + (is (= (string/index-of short-line "├──") + (string/index-of long-line "└──"))))) + (deftest test-time-records-async-stage (async done (let [session (profile/create-session true)] @@ -54,9 +160,10 @@ (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 (re-find #"^\d+ms command=query status=ok$" (first lines)))) + (is (some #(= "stages" (string/trim %)) lines)) (is (some #(string/includes? % "transport.invoke:thread-api/q") lines)) (done)))) (p/catch (fn [e] (is false (str "unexpected error: " e)) - (done))))))) + (done))))))) \ No newline at end of file