status-im
/
timbre
mirror of https://github.com/status-im/timbre.git
2
0
Fork 0
Code Issues Projects Releases Wiki Activity

Profiling: add experimental low-level `profiled` util

This commit is contained in:
Peter Taoussanis 2016-06-23 16:29:14 +07:00
parent 7b9d9b31c8
commit 49830fe798
1 changed files with 30 additions and 11 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

41
src/taoensso/timbre/profiling.clj
View File

@ -201,8 +201,9 @@
`(let [pdata# (-pdata-proxy)] `(let [pdata# (-pdata-proxy)]
(if pdata# (if pdata#
(let [t0# (System/nanoTime) (let [t0# (System/nanoTime)
result# (do ~@body)] result# (do ~@body)
(-capture-time! pdata# ~id (- (System/nanoTime) t0#)) t1# (System/nanoTime)]
(-capture-time! pdata# ~id (- t1# t0#))
result#) result#)
(do ~@body)))))) (do ~@body))))))
@ -210,6 +211,26 @@
(comment (macroexpand '(p :foo (+ 4 2)))) (comment (macroexpand '(p :foo (+ 4 2))))
(defmacro profiled
"Experimental, subject to change!
Low-level profiling util. Executes expr with thread-local profiling
enabled, then executes body with `[<stats> <expr-result>]` binding, e.g:
(profiled \"foo\" [stats result] (do (println stats) result))"
[expr-to-profile params & body]
(assert (vector? params))
(assert (= 2 (count params)))
(let [[stats result] params]
`(try
(-pdata-proxy (-new-pdata))
(let [t0# (System/nanoTime)
~result ~expr-to-profile
t1# (System/nanoTime)
~stats (-compile-final-stats! (- t1# t0#))]
(do ~@body))
(finally (-pdata-proxy nil)))))
(comment (profiled (p :foo "foo") [stats result] [stats result]))
(defmacro profile (defmacro profile
"When logging is enabled, executes named body with thread-local profiling "When logging is enabled, executes named body with thread-local profiling
enabled and logs profiling stats. Always returns body's result." enabled and logs profiling stats. Always returns body's result."
@ -218,21 +239,18 @@
(if elide-profiling? (if elide-profiling?
`(do ~@body) `(do ~@body)
`(if (timbre/log? ~level ~(str *ns*)) ; Runtime check `(if (timbre/log? ~level ~(str *ns*)) ; Runtime check
(try (profiled (do ~@body) [stats# result#]
(-pdata-proxy (-new-pdata)) (let [stats-str# (-format-stats stats#)]
(let [t0# (System/nanoTime)
result# (do ~@body)
stats# (-compile-final-stats! (- (System/nanoTime) t0#))
stats-str# (-format-stats stats#)]
(timbre/log! ~level :p (timbre/log! ~level :p
["Profiling: " ~id "\n" stats-str#] ["Profiling: " ~id "\n" stats-str#]
{:?base-data {:?base-data
{:profile-stats stats# {:profile-stats stats#
:profile-stats-str stats-str#}}) :profile-stats-str stats-str#}})
result#) result#))
(finally (-pdata-proxy nil)))
(do ~@body))))) (do ~@body)))))
(comment (profile :info :foo "foo"))
(defmacro sampling-profile (defmacro sampling-profile
"Like `profile`, but only enables profiling with given probability." "Like `profile`, but only enables profiling with given probability."
[level probability id & body] [level probability id & body]
@ -329,6 +347,7 @@
(p :div (reduce / nums))))) (p :div (reduce / nums)))))
(profile :info :Arithmetic (dotimes [n 100] (my-fn))) (profile :info :Arithmetic (dotimes [n 100] (my-fn)))
(profile :info :high-n (dotimes [n 1e5] (p :nil nil))) ; ~19ms (profile :info :high-n (dotimes [n 1e5] (p :nil nil))) ; ~20ms
(profile :info :high-n (dotimes [n 1e6] (p :nil nil))) ; ~116ms (profile :info :high-n (dotimes [n 1e6] (p :nil nil))) ; ~116ms
(profiled (dotimes [n 1e6] (p :nil nil)) [stats result] [stats result])
(sampling-profile :info 0.5 :sampling-test (p :string "Hello!"))) (sampling-profile :info 0.5 :sampling-test (p :string "Hello!")))