Skip to content

Commit

Permalink
[new] Optimize elapsed time calculator for thread-local case
Browse files Browse the repository at this point in the history
  • Loading branch information
@ptaoussanis
ptaoussanis committed Sep 6, 2023
1 parent f07e330 commit 4f4746e
Show file tree
Hide file tree
Showing 2 changed files with 52 additions and 48 deletions.
98 changes: 51 additions & 47 deletions src/taoensso/tufte/impl.cljc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@

#?(:cljs
(:require-macros
[taoensso.tufte.impl :refer [mt-acc mt-add mt-count atom?]])))
[taoensso.tufte.impl :refer [mt-acc mt-add mt-count]])))

;;;; Mutable accumulators
;; TODO Switch from `atom` to `enc/latom`
Expand Down Expand Up @@ -62,13 +62,13 @@
;; - id-sstats: ?{<id> (<stats/sstats> ...)}

(declare ^:private deref-pdata)
(deftype PState [acc id-times id-sstats])
(deftype PData [^long nmax ^long t0 pstate_]
(deftype PState [dynamic? acc id-times id-sstats])
(deftype PData [overlaps? ^long nmax ^long t0 pstate_]
#?@(:clj [clojure.lang.IDeref (deref [this] (deref-pdata this))]
:cljs [ IDeref (-deref [this] (deref-pdata this))]))

(defn new-pdata-local [^long nmax] (let [t0 (enc/now-nano*)] (PData. nmax t0 (volatile! (PState. (mt-acc) nil nil)))))
(defn new-pdata-dynamic [^long nmax] (let [t0 (enc/now-nano*)] (PData. nmax t0 (atom (PState. (atom nil) nil nil)))))
(defn new-pdata-local [^long nmax] (let [t0 (enc/now-nano*)] (PData. false nmax t0 (volatile! (PState. false (mt-acc) nil nil)))))
(defn new-pdata-dynamic [^long nmax] (let [t0 (enc/now-nano*)] (PData. true nmax t0 (atom (PState. true (atom nil) nil nil)))))

(comment (enc/qb 1e6 (new-pdata-local 10) (new-pdata-dynamic 10))) ; [98.18 138.28]

Expand Down Expand Up @@ -139,44 +139,52 @@
(defn- tspans->tsum
"Returns `tsum` (elapsed time) given collection of `TimeSpan`s.
Based on https://codereview.stackexchange.com/a/126927."
^long [tspans]
^long [overlaps? tspans]
(if (empty? tspans)
0
(let [sorted-tspans (sort-tspans tspans)] ; O(n.logn)
(.-tsum ^ElapsedTimeAcc
(reduce
(fn [^ElapsedTimeAcc acc ^TimeSpan tspan]
(let [t1 (.-t1 tspan)
max-t1 (.-max-t1 acc)]
(if (> t1 max-t1)
(let [t0 (.-t0 tspan)
tsum (.-tsum acc)]
(ElapsedTimeAcc. (+ tsum (- t1 (Math/max t0 max-t1))) t1))
acc)))
(ElapsedTimeAcc. 0 0)
sorted-tspans))))))
(if-not overlaps?
(reduce ; O(n)
(fn [^long tsum ^TimeSpan tspan] (+ tsum (- (.-t1 tspan) (.-t0 tspan))))
0 tspans)

(let [sorted-tspans (sort-tspans tspans)] ; O(n.logn)
(.-tsum ^ElapsedTimeAcc
(reduce ; O(n)
(fn [^ElapsedTimeAcc acc ^TimeSpan tspan]
(let [t1 (.-t1 tspan)
max-t1 (.-max-t1 acc)]
(if (> t1 max-t1)
(let [t0 (.-t0 tspan)
tsum (.-tsum acc)]
(ElapsedTimeAcc. (+ tsum (- t1 (Math/max t0 max-t1))) t1))
acc)))
(ElapsedTimeAcc. 0 0)
sorted-tspans)))))))

(comment
(tspans->tsum nil)
(tspans->tsum [])
(tspans->tsum [(TimeSpan. 1 3) (TimeSpan. 3 6)])
(tspans->tsum [(TimeSpan. 3 6) (TimeSpan. 1 3)])
(tspans->tsum [(TimeSpan. 1 10) (TimeSpan. 3 6)])
(enc/qb 1e6
(tspans->tsum
[(TimeSpan. 10 14)
(TimeSpan. 4 18)
(TimeSpan. 19 20)
(TimeSpan. 19 20)
(TimeSpan. 13 20)])))
(tspans->tsum true nil)
(tspans->tsum true [])
(tspans->tsum true [(TimeSpan. 1 3) (TimeSpan. 3 6)])
(tspans->tsum true [(TimeSpan. 3 6) (TimeSpan. 1 3)])
(tspans->tsum true [(TimeSpan. 1 10) (TimeSpan. 3 6)])
(let [tspans
[(TimeSpan. 10 14)
(TimeSpan. 4 18)
(TimeSpan. 19 20)
(TimeSpan. 19 20)
(TimeSpan. 13 20)]]

(enc/qb 1e6 ; [479.22 87.78]
(tspans->tsum true tspans)
(tspans->tsum false tspans))))

(defn- fast-into [c0 c1] (if (> (count c0) (count c1)) (into c0 c1) (into c1 c0)))
(comment (fast-into nil nil))

(defn- merge-tspans [^long nmax ^long t1 tspans0 tspans1]
(let [tspans2 (fast-into tspans0 tspans1)]
(if (> (count tspans2) nmax) ; Compact, may lose some accuracy
(let [tsum (tspans->tsum tspans2)]
(let [tsum (tspans->tsum true tspans2)]
(list (TimeSpan. (- t1 tsum) t1)))
tspans2)))

Expand Down Expand Up @@ -270,7 +278,7 @@
(transient {})
id-times))))]

{:clock {:t0 t0 :t1 t1 :total (tspans->tsum tspans)}
{:clock {:t0 t0 :t1 t1 :total (tspans->tsum (.-overlaps? pd) tspans)}
:stats public-stats-output}))

(comment @@(new-pdata-local 10))
Expand Down Expand Up @@ -337,28 +345,22 @@
[pd0-id-times pd0-id-sstats]
pd2-ids)

pd2 (PData. nmax pd2-t0 (PState. nil pd2-id-times pd2-id-sstats))]
pd2 (PData. true nmax pd2-t0 (PState. nil nil pd2-id-times pd2-id-sstats))]
(PStats. pd2 ps2-t1 tspans2 (delay (deref-pstats pd2 ps2-t1 tspans2))))

ps0)
ps1)))

;;;; Time capture

#?(:clj
(defmacro ^:private atom? [x]
(if (:ns &env)
`(instance? cljs.core.Atom ~x)
`(instance? clojure.lang.Atom ~x))))

(declare ^:private compact-pstate)
(defn capture-time! [^PData pd id ns-elapsed location-info]
(let [nmax (.-nmax pd)
pstate_ (.-pstate_ pd)
^PState pstate @pstate_
acc (.-acc pstate)]

(if (atom? acc)
(if (.-dynamic? pstate)

;; Dynamic profiling
(let [new-time (Time. id ns-elapsed location-info)
Expand All @@ -373,21 +375,23 @@
(when-let [times ?pulled-times] ; Do compaction, rare
(let [t0 (enc/now-nano*)]
;; Contention against `pstate_` unlikely since we just drained `acc`
(swap! pstate_ (fn [pstate] (compact-pstate pstate times nmax true)))
(swap! pstate_ (fn [pstate] (compact-pstate pstate times nmax)))
(recur pd :tufte/compaction (- (enc/now-nano*) t0) nil))))

(do ; Common case: thread-local profiling
;; Common case: thread-local profiling
(do
(mt-add acc (Time. id ns-elapsed location-info))

(when (> (mt-count acc) nmax) ; Do compaction, rare
(let [t0 (enc/now-nano*)]
(vreset! pstate_ (compact-pstate pstate acc nmax false))
(vreset! pstate_ (compact-pstate pstate acc nmax))
(recur pd :tufte/compaction (- (enc/now-nano*) t0) nil)))))))

(defn- compact-pstate [^PState pstate pulled-times ^long nmax dynamic?]
(defn- compact-pstate [^PState pstate pulled-times ^long nmax]
;; Note that compaction expense doesn't distort p times unless there's
;; p nesting (where outer p time includes inner p's capture time).
(let [id-times (.-id-times pstate)
(let [dynamic? (.-dynamic? pstate)
id-times (.-id-times pstate)
id-sstats (.-id-sstats pstate)
id-times (times-into-id-times id-times pulled-times)

Expand All @@ -408,7 +412,7 @@

new-acc (if dynamic? (.-acc pstate) (mt-acc))]

(PState. new-acc id-times id-sstats)))
(PState. dynamic? new-acc id-times id-sstats)))

(comment
(try
Expand Down
2 changes: 1 addition & 1 deletion test/taoensso/tufte_tests.cljc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -244,7 +244,7 @@
(is (<= (count (:foo (.-id-sstats ^PState (.-pstate_ ^PData (.-pd ^PStats ps))))) 10))])]))

(defn- pstats-tspan [t0 t1]
(let [pd (PData. 8e5 t0 (PState. nil nil nil))
(let [pd (PData. false 8e5 t0 (PState. true nil nil nil))
time-span [(TimeSpan. t0 t1)]]
(PStats. pd t1 time-span (delay (#'impl/deref-pstats pd t1 time-span)))))

Expand Down

0 comments on commit 4f4746e

Please sign in to comment.