[profile] Update to latest profiling middleware

alexander-yakushev · alexander-yakushev · commit 09c036dd2974 · 2025-04-10T16:34:53.000+03:00
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -26,6 +26,7 @@
 - [#3789](https://github.com/clojure-emacs/cider/issues/3796): Completion: disable client-side sorting (defer to backend-provided candidate order).
 - [#3797](https://github.com/clojure-emacs/cider/issues/3797): Completion: enable `cider-completion-style` by default (this enables richer completion suggestions where candidates don't have to strictly match the prefix).
 - [#3803](https://github.com/clojure-emacs/cider/pull/3803): Enable dynamic indentation for `clojure-ts-mode`.
+- [#3805](https://github.com/clojure-emacs/cider/pull/3805): Profiler: update to latest profiling middleware.
 
 ### Bugs fixed
 
diff --git a/cider-mode.el b/cider-mode.el
@@ -673,7 +673,7 @@ The result depends on the buffer CIDER connection type."
 (defface cider-traced-face
   '((((type graphic)) :box (:color "cyan" :line-width -1))
     (t :underline t :background "#066"))
-  "Face used to mark code being traced."
+  "Face used to mark functions being traced or profiled."
   :group 'cider
   :package-version '(cider . "0.11.0"))
 
@@ -805,11 +805,11 @@ with the given LIMIT."
                           (push sym instrumented))
                          (`"\"light-form\""
                           (push sym enlightened)))
-                       ;; The ::traced keywords can be inlined by MrAnderson, so
-                       ;; we catch that case too.
                        ;; FIXME: This matches values too, not just keys.
-                       (when (seq-find (lambda (k) (and (stringp k)
-                                                        (string-match (rx "orchard.trace/traced" eos) k)))
+                       (when (seq-find (lambda (k)
+                                         (and (stringp k)
+                                              (or (string= "orchard.trace/traced" k)
+                                                  (string= "orchard.profile/profiled" k))))
                                        meta)
                          (push sym traced))
                        (when (and do-deprecated (nrepl-dict-get meta "deprecated"))
diff --git a/cider-profile.el b/cider-profile.el
@@ -28,6 +28,7 @@
 (require 'cider-client)
 (require 'cider-popup)
 (require 'cider-eval)
+(require 'cider-inspector)
 
 (defconst cider-profile-buffer "*cider-profile*")
 
@@ -37,16 +38,10 @@
     (define-key map (kbd "C-t") #'cider-profile-toggle)
     (define-key map (kbd "c") #'cider-profile-clear)
     (define-key map (kbd "C-c") #'cider-profile-clear)
-    (define-key map (kbd "S") #'cider-profile-summary)
-    (define-key map (kbd "C-S") #'cider-profile-summary)
-    (define-key map (kbd "s") #'cider-profile-var-summary)
-    (define-key map (kbd "C-s") #'cider-profile-var-summary)
+    (define-key map (kbd "s") #'cider-profile-summary)
+    (define-key map (kbd "C-s") #'cider-profile-summary)
     (define-key map (kbd "n") #'cider-profile-ns-toggle)
     (define-key map (kbd "C-n") #'cider-profile-ns-toggle)
-    (define-key map (kbd "v") #'cider-profile-var-profiled-p)
-    (define-key map (kbd "C-v") #'cider-profile-var-profiled-p)
-    (define-key map (kbd "+") #'cider-profile-samples)
-    (define-key map (kbd "C-+") #'cider-profile-samples)
     map)
   "CIDER profiler keymap.")
 
@@ -55,9 +50,6 @@
     ["Toggle var profiling" cider-profile-toggle]
     ["Toggle namespace profiling" cider-profile-ns-toggle]
     "--"
-    ["Display var profiling status" cider-profile-var-profiled-p]
-    ["Display max sample count" cider-profile-samples]
-    ["Display var summary" cider-profile-var-summary]
     ["Display summary" cider-profile-summary]
     ["Clear data" cider-profile-clear])
   "CIDER profiling submenu.")
@@ -69,66 +61,20 @@ Optional argument BUFFER defaults to current buffer."
   (nrepl-make-response-handler
    (or buffer (current-buffer)) handler nil nil nil))
 
-;;;###autoload
-(defun cider-profile-samples (&optional query)
-  "Displays current max-sample-count.
-If optional QUERY is specified, set max-sample-count and display new value."
-  (interactive "P")
-  (cider-ensure-op-supported "set-max-samples")
-  (cider-ensure-op-supported "get-max-samples")
-  (if (not (null query))
-      (cider-nrepl-send-request
-       (let ((max-samples (if (numberp query) query '())))
-         (message "query: %s" max-samples)
-         `("op" "set-max-samples" "max-samples" ,max-samples))
-       (cider-profile--make-response-handler
-        (lambda (_buffer value)
-          (let ((value (if (zerop (length value)) "unlimited" value)))
-            (message "max-sample-count is now %s" value)))))
-    (cider-nrepl-send-request
-     '("op" "get-max-samples")
-     (cider-profile--make-response-handler
-      (lambda (_buffer value)
-        (let ((value (if (zerop (length value)) "unlimited" value)))
-          (message "max-sample-count is now %s" value))))))
-  query)
-
-;;;###autoload
-(defun cider-profile-var-profiled-p (query)
-  "Displays the profiling status of var under point.
-Prompts for var if none under point or QUERY is present."
-  (interactive "P")
-  (cider-ensure-op-supported "is-var-profiled")
-  (cider-read-symbol-name
-   "Report profiling status for var: "
-   (lambda (sym)
-     (let ((ns (cider-current-ns)))
-       (cider-nrepl-send-request
-        `("op" "is-var-profiled"
-          "ns" ,ns
-          "sym" ,sym)
-        (cider-profile--make-response-handler
-         (lambda (_buffer value)
-           (pcase value
-             ("profiled" (message "Profiling is currently enabled for %s/%s" ns sym))
-             ("unprofiled" (message "Profiling  is currently disabled for %s/%s" ns sym))
-             ("unbound" (message "%s/%s is unbound" ns sym)))))))))
-  query)
-
 ;;;###autoload
 (defun cider-profile-ns-toggle (&optional query)
   "Toggle profiling for the ns associated with optional QUERY.
 
 If optional argument QUERY is non-nil, prompt for ns.  Otherwise use
 current ns."
   (interactive "P")
-  (cider-ensure-op-supported "toggle-profile-ns")
+  (cider-ensure-op-supported "cider/profile-toggle-ns")
   (let ((ns (if query
                 (completing-read "Toggle profiling for ns: "
                                  (cider-sync-request:ns-list))
               (cider-current-ns))))
     (cider-nrepl-send-request
-     `("op" "toggle-profile-ns"
+     `("op" "cider/profile-toggle-ns"
        "ns" ,ns)
      (cider-profile--make-response-handler
       (lambda (_buffer value)
@@ -143,69 +89,42 @@ current ns."
 Defaults to the symbol at point.
 With prefix arg or no symbol at point, prompts for a var."
   (interactive "P")
-  (cider-ensure-op-supported "toggle-profile")
+  (cider-ensure-op-supported "cider/profile-toggle-var")
   (cider-read-symbol-name
    "Toggle profiling for var: "
    (lambda (sym)
      (let ((ns (cider-current-ns)))
        (cider-nrepl-send-request
-        `("op" "toggle-profile"
+        `("op" "cider/profile-toggle-var"
           "ns" ,ns
           "sym" ,sym)
         (cider-profile--make-response-handler
          (lambda (_buffer value)
            (pcase value
              ("profiled" (message "Profiling enabled for %s/%s" ns sym))
-             ("unprofiled" (message "Profiling disabled for %s/%s" ns sym))
-             ("unbound" (message "%s/%s is unbound" ns sym)))))))))
+             ("unprofiled" (message "Profiling disabled for %s/%s" ns sym)))))))))
   query)
 
-(defun cider-profile-display-stats (stats-response)
-  "Displays the STATS-RESPONSE on `cider-profile-buffer`."
-  (let ((table (nrepl-dict-get stats-response "err")))
-    (if cider-profile-buffer
-        (let ((buffer (cider-make-popup-buffer cider-profile-buffer)))
-          (with-current-buffer buffer
-            (let ((inhibit-read-only t)) (insert table)))
-          (display-buffer buffer)
-          (let ((window (get-buffer-window buffer)))
-            (set-window-point window 0)
-            (select-window window)
-            (fit-window-to-buffer window)))
-      (cider-emit-interactive-eval-err-output table))))
+(defun cider-profile--send-to-inspector (summary-response)
+  "Displays SUMMARY-RESPONSE using the inspector."
+  (let ((value (nrepl-dict-get summary-response "value")))
+    (cider-inspector--render-value value)))
 
 ;;;###autoload
 (defun cider-profile-summary ()
   "Display a summary of currently collected profile data."
   (interactive)
-  (cider-ensure-op-supported "profile-summary")
-  (cider-profile-display-stats
-   (cider-nrepl-send-sync-request '("op" "profile-summary"))))
-
-;;;###autoload
-(defun cider-profile-var-summary (query)
-  "Display profile data for var under point QUERY.
-Defaults to the symbol at point.  With prefix arg or no symbol at point,
-prompts for a var."
-  (interactive "P")
-  (cider-ensure-op-supported "profile-var-summary")
-  (cider-read-symbol-name
-   "Profile-summary for var: "
-   (lambda (sym)
-     (cider-profile-display-stats
-      (cider-nrepl-send-sync-request
-       `("op" "profile-var-summary"
-         "ns" ,(cider-current-ns)
-         "sym" ,sym)))))
-  query)
+  (cider-ensure-op-supported "cider/profile-summary")
+  (cider-inspector--render-value
+   (cider-nrepl-send-sync-request '("op" "cider/profile-summary"))))
 
 ;;;###autoload
 (defun cider-profile-clear ()
   "Clear any collected profile data."
   (interactive)
-  (cider-ensure-op-supported "clear-profile")
+  (cider-ensure-op-supported "cider/profile-clear")
   (cider-nrepl-send-request
-   '("op" "clear-profile")
+   '("op" "cider/profile-clear")
    (cider-profile--make-response-handler
     (lambda (_buffer value)
       (when (equal value "cleared")
diff --git a/doc/modules/ROOT/pages/config/syntax_highlighting.adoc b/doc/modules/ROOT/pages/config/syntax_highlighting.adoc
@@ -56,5 +56,5 @@ should take care of them):
 
 * `cider-deprecated-face` - used for syntax highlighting deprecated vars
 * `cider-instrumented-face` - used for syntax highlighting instrumented for debugging vars
-* `cider-traced-face` - used for syntax highlighting traced vars
+* `cider-traced-face` - used for syntax highlighting traced and profiled vars
 * `cider-reader-conditional-face` - used for syntax highlighting inactive reader conditional branches
diff --git a/doc/modules/ROOT/pages/debugging/profiling.adoc b/doc/modules/ROOT/pages/debugging/profiling.adoc
@@ -1,47 +1,57 @@
 = Profiling
 
-CIDER has a built-in profiler that can help you identify hot-spots in your
-application code. It's built on top of the https://github.com/thunknyc/profile[thunknyc/profile] library.
+CIDER has a simple built-in profiler that can you to quickly measure the running
+time of individual functions. It is similar to wrapping your functions with
+`time` macro, except it records every timing and displays a the summarized
+result.
+
+NOTE: Profiling is different from benchmarking. Benchmarking more accurately
+tells you how long the code executes. If you need accurate timing results, use a
+serious benchmarking library like
+https://github.com/hugoduncan/criterium[Criterium]. If you need to understand
+where most of the time is spent, use a serious profiler like
+https://github.com/clojure-goes-fast/clj-async-profiler[clj-async-profiler].
 
 NOTE: The profiler doesn't support ClojureScript.
 
 == Usage
 
-Using CIDER's profiler is super easy. You'd just identify
-the vars you'd want to profile and invoke
-`M-x cider-profile-toggle` (kbd:[C-c C-= t]). By defaults it operates on the symbol
-at point, but will prompt for a var if there's nothing under the point.
+To start using CIDER profiler, choose the vars you want to profile and invoke
+`M-x cider-profile-toggle` (kbd:[C-c C-= t]). By defaults it operates on the
+symbol at point, but will prompt for a var if there's nothing under the point.
+You can also mark all functions in the namespace for profiling via
+`cider-profile-ns-toggle` (kbd:[C-c C-= n]).
 
-TIP: There's also `cider-profile-ns-toggle` (kbd:[C-c C-= n]) that will profiles all vars in a
-namespace.
+Then, evaluate some code making use of those vars and their invocations will be
+automatically profiled.
 
-Afterwards you can evaluate some code making use of those vars and their
-invocations will be automatically profiled.
-
-You can display a report of the collected profiling data with `M-x cider-profile-summary` (kbd:[C-c C-= S]). If you'd like to limit the displayed data to a particular var you should try
-`M-x cider-profile-var-summary` (kbd:[C-c C-= s]).
+You can display a report of the collected profiling data with `M-x
+cider-profile-summary` (kbd:[C-c C-= s]).
 
 == Understanding the Report Format
 
-A typical profiling report looks something like this:
+Profiling reports are rendered by xref:debugging/inspector.adoc[CIDER
+inspector]. A typical profiling report looks like this:
 
 ....
-|          :name | :n | :sum | :q1 | :med | :q3 | :sd | :mad |
-|----------------+----+------+-----+------+-----+-----+------|
-|  #'user/my-add |  1 |  2µs | 2µs |  2µs | 2µs | 0µs |  0µs |
-| #'user/my-mult |  2 | 11µs | 3µs |  8µs | 3µs | 3µs |  5µs |
+| # |           :name |   :n |  :mean |    :std |   :sum |   :min |   :max |   :med |   :samples |
+|---+-----------------+------+--------+---------+--------+--------+--------+--------+------------|
+| 0 | #'sample-ns/bar | 1000 |   3 us |  ±14 us |   3 ms | 791 ns | 384 us |   2 us |  [791 ...] |
+| 1 | #'sample-ns/baz | 1000 | 307 ns | ±710 ns | 307 us |  84 ns |  22 us | 250 ns |   [84 ...] |
+| 2 | #'sample-ns/foo | 1000 |   7 us |  ±18 us |   7 ms |   3 us | 495 us |   5 us | [2584 ...] |
+| 3 | #'sample-ns/qux | 1000 |   8 us |  ±20 us |   8 ms |   3 us | 543 us |   5 us | [3125 ...] |
 ....
 
 Let's demystify all the column names:
 
 * `:n`: Number of samples.
+* `:mean`: Average time spent in fn.
+* `:std`: Standard deviation.
 * `:sum`: Aggregate time spent in fn.
-* `:q1`: First quartile i.e. twenty-fifth percentile.
+* `:min`: Minimal recorded time for fn.
+* `:min`: Maximal recorded time for fn.
 * `:med`: Median i.e. fiftieth percentile.
-* `:q3`: Third quartile i.e. seventy-fifth percentile.
-* `:sd`: Standard deviation i.e. the square root of the sum of squares
-  of differences from the mean.
-* `:mad`: Mean absolute deviation. See https://en.wikipedia.org/wiki/Average_absolute_deviation[this article] for more details.
+* `:samples`: A list of all timing samples. You can click it to see the full list in the inspector.
 
 == Keybindings
 
@@ -56,22 +66,10 @@ Let's demystify all the column names:
 | kbd:[C-c C-= n]
 | Toggle profiling for the current ns.
 
-| `cider-profile-var-profiled-p`
-| kbd:[C-c C-= v]
-| Show whether some var has profiling enabled or not.
-
-| `cider-profile-var-summary`
-| kbd:[C-c C-= s]
-| Display the profiling summary for some var.
-
 | `cider-profile-summary`
-| kbd:[C-c C-= S]
+| kbd:[C-c C-= s]
 | Display the profiling summary for all vars.
 
-| `cider-profile-samples`
-| kbd:[C-c C-= +]
-| Display or update `max-sample-count`.
-
 | `cider-profile-clear`
 | kbd:[C-c C-= c]
 | Clear profiling data.
