Skip to content

Commit

Permalink
[new] NB completely rewrite core
Browse files Browse the repository at this point in the history 
Refreshes the core implementation as I'd write it today.

Changes include:

  - Major code simplifications
  - Significant performance improvements
  • Loading branch information
@ptaoussanis
ptaoussanis committed Sep 8, 2023
1 parent e3938ed commit baac41c
Show file tree
Hide file tree
Showing 4 changed files with 433 additions and 429 deletions.
2 changes: 1 addition & 1 deletion project.clj
View file
Original file line number Diff line number Diff line change
@@ -1,4 +1,4 @@
(defproject com.taoensso/tufte "2.6.1"
(defproject com.taoensso/tufte "2.7.0-alpha2"
:author "Peter Taoussanis <https://www.taoensso.com>"
:description "Simple performance monitoring for Clojure/Script applications"
:url "https://github.com/taoensso/tufte"
Expand Down
103 changes: 52 additions & 51 deletions src/taoensso/tufte.cljc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -33,16 +33,25 @@
{:author "Peter Taoussanis (@ptaoussanis)"}

(:require
[taoensso.encore :as enc :refer [have have?]]
[taoensso.tufte.stats :as stats]
[taoensso.encore :as enc :refer [have have?]]
[taoensso.encore.runner :as runner]
[taoensso.tufte.stats :as stats]

#?(:clj [taoensso.tufte.impl :as impl]
:cljs [taoensso.tufte.impl :as impl :refer [PStats]]))

#?(:clj (:import [taoensso.tufte.impl PStats]))
#?(:clj (:import [taoensso.tufte.impl PStats]))
#?(:cljs (:require-macros [taoensso.tufte :refer [profiled]])))

(enc/assert-min-encore-version [3 66 0])
(comment (remove-ns 'taoensso.tufte))

(enc/assert-min-encore-version [3 67 0])

;;;; TODO
;; - Use new `enc/ctx-filter` and config utils for filtering.
;; - Add gs pid stack (w/ max length and recursion detection).
;; - Use new Telemere-style handler registration, with per-handler opts?
;; Replace impl/handler-runner, and accumulating-handler runner.

;;;; Level filtering
;; Terminology note: we distinguish between call/form and min levels to ensure
Expand Down Expand Up @@ -175,9 +184,10 @@
(not (string? ns-str-form)) ; Not a compile-time ns-str const
(may-profile-ns? compile-time-ns-filter ns-str-form))))))

;;;; Output handlers
;; Handlers are used for `profile` output, let us nicely decouple stat
;; creation and consumption.
;;;; `profile` handlers
;; Handlers decouples stat creation and consumption

#?(:clj (enc/defalias impl/handler-runner-opts))

(defrecord HandlerVal [ns-str level ?id ?data pstats pstats-str_ ?file ?line])

Expand Down Expand Up @@ -311,16 +321,14 @@
(impl/new-pdata-local nmax))))

(comment
@@(new-pdata)

;; Note that dynamic pdata with non-dynamic `with-profiling` is fine:
@((new-pdata))
(let [pd (new-pdata)
t0 (System/nanoTime)]
;; Note that dynamic pdata with non-dynamic `with-profiling` is fine:
(with-profiling pd {}
(p :foo (Thread/sleep 100))
(capture-time! pd :bar (- t0 (System/nanoTime))))
@pd) ; => pstats
)
(p :pid1 (Thread/sleep 100))
(pd :pid2 (- t0 (System/nanoTime)) nil))
@(pd)))

#?(:clj
(defmacro with-profiling
Expand Down Expand Up @@ -349,17 +357,17 @@
See `new-pdata` for more info on low-level primitives.
See also `capture-time!*`."
([pdata id nano-secs-elapsed] `(impl/capture-time! ~pdata ~id ~nano-secs-elapsed ~(enc/get-source &form &env)))
([pdata id nano-secs-elapsed] `(~pdata ~id ~nano-secs-elapsed ~(enc/get-source &form &env)))
([ id nano-secs-elapsed]
`(when-let [~'pd (or impl/*pdata* (impl/pdata-local-get))]
(impl/capture-time! ~'pd ~id ~nano-secs-elapsed ~(enc/get-source &form &env))))))
(~'pd ~id ~nano-secs-elapsed ~(enc/get-source &form &env))))))

(defn capture-time!*
"Like `capture-time!` but: a function, and does not collect callsite location info."
([pdata id nano-secs-elapsed] (impl/capture-time! pdata id nano-secs-elapsed nil))
([pdata id nano-secs-elapsed] (pdata id nano-secs-elapsed nil))
([ id nano-secs-elapsed]
(when-let [pd (or impl/*pdata* (impl/pdata-local-get))]
(impl/capture-time! pd id nano-secs-elapsed nil))))
(pd id nano-secs-elapsed nil))))

(comment
@(second
Expand All @@ -370,14 +378,14 @@
(capture-time! :foo (- t1 t0)))))

(let [pd (new-pdata)]
(enc/qb 1e6 (capture-time! pd :foo 100))
@@pd)
(enc/qb 1e6 (pd :foo 100 nil))
@(pd))

(let [pd (new-pdata)]
(with-profiling pd {}
(p :foo (Thread/sleep 100))
(p :bar (Thread/sleep 200)))
@@pd))
@(pd)))

;;;; Core macros

Expand Down Expand Up @@ -631,7 +639,7 @@
;; ~(println [id-form (:line loc)]) ; Debug location info

;; Note that `capture-time!` expense is excl. from p time
(impl/capture-time! ~'__pd ~id-form (- ~'__t1 ~'__t0) ~loc )
(~'__pd ~id-form (- ~'__t1 ~'__t0) ~loc )
~'__result)

(do ~@body)))))))
Expand Down Expand Up @@ -794,14 +802,15 @@
(defn- sacc-add! [pstats_ group-id ps]
(when (and group-id ps)
;; Contention would be expensive, consumer should serialize:
(swap! pstats_ (fn [m] (assoc m group-id (impl/merge-pstats (get m group-id) ps))))
(pstats_ group-id #(impl/merge-pstats % ps))
true))

(deftype StatsAccumulator [pstats_] ; {<group-id> <pstats>}
#?@(:clj [clojure.lang.IFn (invoke [_ group-id ps] (sacc-add! pstats_ group-id ps))]
:cljs [ IFn (-invoke [_ group-id ps] (sacc-add! pstats_ group-id ps))])
(deftype StatsAccumulator [pstats_]
;; `pstats` - {<group-id> <pstats>}
#?@(:clj [clojure.lang.IDeref (deref [_] (sacc-drain-and-merge! pstats_))]
:cljs [ IDeref (-deref [_] (sacc-drain-and-merge! pstats_))]))
:cljs [ IDeref (-deref [_] (sacc-drain-and-merge! pstats_))])
#?@(:clj [clojure.lang.IFn (invoke [_] (sacc-drain-and-merge! pstats_)) (invoke [_ group-id ps] (sacc-add! pstats_ group-id ps))]
:cljs [ IFn (-invoke [_] (sacc-drain-and-merge! pstats_)) (-invoke [_ group-id ps] (sacc-add! pstats_ group-id ps))]))

(defn stats-accumulator
"Alpha, subject to change.
Expand All @@ -814,9 +823,9 @@
Note that you may want some kind of async/buffer/serialization
mechanism in front of merge calls for performance (e.g. by using an agent).
See also `add-accumulating-handler!`, example clj project."
See also `add-accumulating-handler!` example clj project."

[] (StatsAccumulator. (atom {})))
[] (StatsAccumulator. (enc/latom {})))

(comment
(enc/qb 1e6 (stats-accumulator)) ; 66.75
Expand All @@ -829,20 +838,18 @@
(defn add-accumulating-handler!
"Alpha, subject to change.
Creates a new StatsAccumulator (and agent in clj), then
registers a handler to accumulate `profile` output to the
StatsAccumulator using the agent.
Creates a new StatsAccumulator and registeres a handler to
accumulate `profile` output to the StatsAccumulator.
Returns the StatsAccumulator. You can deref the result to
drain the accumulator and return {<group-id> <merged-pstats>}.
Returns the StatsAccumulator.
Deref it to drain the accumulator and return {<group-id> <merged-pstats>}.
One common pattern is to deref the accumulator every n
minutes/etc. to get a view of total-system performance over
the period, e.g.:
One common pattern is to deref the accumulator every n minutes/etc.
to get a view of total-system performance over the period, e.g.:
(defonce my-sacc (add-accumulating-handler! {:ns-pattern \"*\"}))
(defonce my-sacc-drainer
;; Will drain and print formatted stats every minute
;; Drain and print formatted stats every minute
(future
(while true
(when-let [m (not-empty @my-sacc)]
Expand All @@ -854,18 +861,20 @@
See also `format-grouped-pstats`, example clj project."

[{:keys [ns-pattern handler-id]
[{:keys [ns-pattern handler-id runner-opts]
:or {ns-pattern "*"
handler-id :accumulating}}]

(let [sacc (stats-accumulator)
agent_ #?(:clj (delay (agent nil :error-mode :continue)) :cljs nil)]
;; runner #?(:clj (runner/runner (conj {:daemon-threads? true} runner-opts)) :cljs nil)
runner (fn [f] (f))
]

(add-handler! handler-id ns-pattern
(fn [{:keys [?id ?data pstats]}]
(let [id (or ?id :tufte/nil-id)]
#?(:clj (send @agent_ (fn [_] (sacc id pstats)))
:cljs (sacc id pstats)))))
#?(:clj (runner (fn [] (sacc id pstats)))
:cljs (sacc id pstats)))))

sacc))

Expand All @@ -879,7 +888,7 @@

(defn format-grouped-pstats
"Alpha, subject to change.
Takes a map of {<group-id> <PStats>} and formats a combined
Takes a map of {<group-id> <pstats>} and formats a combined
output string using `format-pstats`.
See also example clj project."
Expand Down Expand Up @@ -993,11 +1002,3 @@
(format-pstats
(second
(profiled {} (p :foo (Thread/sleep 100)))))))

(comment ; Disjoint time union
(let [[_ ps1] (profiled {} (p :foo (Thread/sleep 100)))
_ (Thread/sleep 500)
[_ ps2] (profiled {} (p :foo (Thread/sleep 100)))]
(println (format-pstats (merge-pstats ps2 ps1)))
;;@(merge-pstats ps2 ps1)
))
Loading

0 comments on commit baac41c

Please sign in to comment.