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

Added unaccounted-for timer. Fixed bug with :mean overflow.

This commit is contained in:
Peter Taoussanis 2012-07-03 20:50:06 +07:00
parent 0cb368a0d9
commit 123f3c51d9
2 changed files with 43 additions and 24 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

25
README.md
View File

@ -191,8 +191,8 @@ Wrap forms that you'd like to profile with the `p` macro and give them a name:
(defn my-fn
[]
(let [nums (vec (range 1000))]
(+ (p :fast-thread (Thread/sleep 1) 10)
(p :slow-thread (Thread/sleep 2) 32)
(+ (p :fast-sleep (Thread/sleep 1) 10)
(p :slow-sleep (Thread/sleep 2) 32)
(p :add (reduce + nums))
(p :sub (reduce - nums))
(p :mult (reduce * nums))
@ -207,20 +207,21 @@ The `profile` macro can now be used to log times for any wrapped forms:
```clojure
(profile :info :Arithmetic (dotimes [n 100] (my-fn)))
=> "Done!"
%> 2012-Jul-03 19:39:12 +0700 INFO [my-app] - Profiling: my-app/Arithmetic
Name Count Min Max Mean Total% Total
my-app/slow-thread 100 2ms 2ms 2ms 62 232ms
my-app/fast-thread 100 1ms 1ms 1ms 32 119ms
my-app/div 100 64μs 146μs 79μs 2 7ms
my-app/add 100 24μs 107μs 54μs 1 5ms
my-app/mult 100 33μs 92μs 42μs 1 4ms
my-app/sub 100 30μs 124μs 42μs 1 4ms
373ms
%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling: my-app/Arithmetic
Name Count Min Max Mean Total% Total
my-app/slow-sleep 100 2ms 2ms 2ms 58 232ms
my-app/fast-sleep 100 1ms 1ms 1ms 30 120ms
my-app/div 100 65μs 204μs 90μs 2 9ms
my-app/add 100 32μs 116μs 59μs 1 5ms
my-app/sub 100 30μs 145μs 47μs 1 4ms
my-app/mult 100 33μs 117μs 45μs 1 4ms
Unaccounted 6 25ms
Total 100 403ms
```
It's important to note that Timbre profiling is fully **log-level aware**: if the logging level is insufficient, you won't pay for profiling. Likewise, normal namespace filtering applies. (Performance characteristics for both checks are inherited from Timbre itself).
And since `p` and `profile` **always return their body's result** regardless of whether profiling actually happens or not, it becomes feasible to use profiling more often as part of your normal workflow: just *leave profiling code in production as you do logging code*.
And since `p` and `profile` **always return their body's result** regardless of whether profiling actually happens or not, it becomes feasible to use profiling more often as part of your normal workflow: just *leave profiling code in production as you do for logging code*.
A **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`.

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

@ -5,11 +5,18 @@
(def ^:dynamic *plog* "{::pname [time1 time2 ...] ...}" nil)
(defmacro prepare-name
"Returns namespaced keyword for given name."
[name]
`(if (and (keyword? ~name) (namespace ~name))
~name
(keyword (str ~*ns*) (clojure.core/name ~name))))
(defmacro p
"When in the context of a *plog* binding, records execution time of named
body. Always returns the body's result."
[name & body]
(let [name (keyword (str *ns*) (clojure.core/name name))]
(let [name (prepare-name name)]
`(if *plog*
(let [start-time# (System/nanoTime)
result# (do ~@body)
@ -27,7 +34,7 @@
(assoc m pname {:count count
:min (apply min times)
:max (apply max times)
:mean (int (/ total count))
:mean (long (/ total count))
:total total})))
{} plog))
@ -40,12 +47,19 @@
"Returns formatted plog stats table for given plog stats."
([stats] (plog-table stats :total))
([stats sort-field]
(let [grand-total-time (reduce + (map :total (vals stats)))
max-name-width (apply max (map (comp count str)
(conj (keys stats) "Name")))
(let [;; How long entire (profile) body took
total-time (-> stats :meta/total :total)
stats (dissoc stats :meta/total)
;; Sum of (p) times, <= total-time
accounted (reduce + (map :total (vals stats)))
max-name-width (apply max (map (comp count str)
(conj (keys stats) "Unaccounted")))
pattern (str "%" max-name-width "s %6d %9s %10s %9s %7d %1s%n")
s-pattern (.replace pattern \d \s)
perc #(Math/round (/ %1 %2 0.01))
ft (fn [nanosecs]
(let [pow #(Math/pow 10 %)
ok-pow? #(>= nanosecs (pow %))
@ -53,7 +67,7 @@
(cond (ok-pow? 9) (str (to-pow 9) "s")
(ok-pow? 6) (str (to-pow 6) "ms")
(ok-pow? 3) (str (to-pow 3) "μs")
:else (str (long nanosecs) "ns"))))]
:else (str (long nanosecs) "ns"))))]
(with-out-str
(printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total")
@ -62,17 +76,20 @@
(sort-by #(- (get-in stats [% sort-field]))))]
(let [{:keys [count min max mean total]} (stats pname)]
(printf pattern (fqname pname) count (ft min) (ft max) (ft mean)
(Math/round (/ total grand-total-time 0.01))
(perc total total-time)
(ft total))))
(printf s-pattern "" "" "" "" "" "" (ft grand-total-time))))))
(let [unacc (- total-time accounted)
unacc-perc (perc unacc total-time)]
(printf s-pattern "Unaccounted" "" "" "" "" unacc-perc (ft unacc))
(printf s-pattern "Total" "" "" "" "" 100 (ft total-time)))))))
(defmacro profile*
"Executes named body with profiling enabled. Body forms wrapped in (p) will be
timed and time stats sent along with `name` to binary `log-fn`. Returns body's
result."
[log-fn name & body]
(let [name (keyword (str *ns*) (clojure.core/name name))]
(let [name (prepare-name name)]
`(binding [*plog* (atom {})]
(let [result# (do ~@body)]
(~log-fn ~name (plog-stats @*plog*))
@ -97,7 +114,7 @@
(str "Profiling: " (fqname name#))
(str "\n" (plog-table stats#))))
~name
~@body)
(p :meta/total ~@body))
(do ~@body)))
(defmacro sampling-profile
@ -110,6 +127,7 @@
(comment
(profile :info :Sleepy-threads
(Thread/sleep 100) ; Unaccounted
(p :1ms (Thread/sleep 1))
(p :2s (Thread/sleep 2000))
(p :50ms (Thread/sleep 50))
@ -121,8 +139,8 @@
(defn my-fn
[]
(let [nums (vec (range 1000))]
(+ (p :fast-thread (Thread/sleep 1) 10)
(p :slow-thread (Thread/sleep 2) 32)
(+ (p :fast-sleep (Thread/sleep 1) 10)
(p :slow-sleep (Thread/sleep 2) 32)
(p :add (reduce + nums))
(p :sub (reduce - nums))
(p :mult (reduce * nums))