mirror of
https://github.com/logseq/logseq.git
synced 2026-05-17 17:32:35 +00:00
enhance(cli): update --profile output
This commit is contained in:
rcmerci
@@ -250,6 +250,15 @@ 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 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.
|
||||
|
||||
@@ -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)))))
|
||||
@@ -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))))))
|
||||
@@ -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)))))))
|
||||
Reference in New Issue
Block a user