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

Added Mean Absolute Deviation (MAD) times to profiling output. Misc housekeeping.

This commit is contained in:
Peter Taoussanis 2012-07-04 13:47:21 +07:00
parent 2aa9d4d83f
commit 19f7b898e3
3 changed files with 30 additions and 25 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

24
README.md
View File

@ -207,23 +207,23 @@ 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 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
%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling my-app/Arithmetic
Name Calls Min Max MAD Mean Total% Total
my-app/slow-sleep 100 2ms 2ms 31μs 2ms 57 231ms
my-app/fast-sleep 100 1ms 1ms 27μs 1ms 29 118ms
my-app/add 100 44μs 2ms 46μs 100μs 2 10ms
my-app/sub 100 42μs 564μs 26μs 72μs 2 7ms
my-app/div 100 54μs 191μs 17μs 71μs 2 7ms
my-app/mult 100 31μs 165μs 11μs 44μs 1 4ms
Unaccounted 6 26ms
Total 100 405ms
```
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).
It's important to note that Timbre profiling is fully **logging-level aware**: if the 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 for logging code*.
A **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`.
A simple **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`.
## Timbre Supports the ClojureWerkz Project Goals

2
src/taoensso/timbre.clj
View File

@ -217,7 +217,7 @@
(not-any? (partial ns-match? ns) ns-blacklist))))))
(reset! ns-filter-cache)))
;;; Prime initial caches and recache on config change
;;; Prime initial caches and re-cache on config change
(cache-appenders-juxt!)
(cache-ns-filter!)

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

@ -30,11 +30,17 @@
[plog]
(reduce (fn [m [pname times]]
(let [count (count times)
total (reduce + times)]
total (reduce + times)
mean (long (/ total count))
;; Mean Absolute Deviation
mad (long (/ (reduce + (map #(Math/abs (long (- % mean)))
times))
count))]
(assoc m pname {:count count
:min (apply min times)
:max (apply max times)
:mean (long (/ total count))
:mean mean
:mad mad
:total total})))
{} plog))
@ -44,7 +50,7 @@
(str (namespace keyword) "/" (name keyword)))
(defn plog-table
"Returns formatted plog stats table for given plog stats."
"Returns formatted table string for given plog stats."
([stats] (plog-table stats :total))
([stats sort-field]
(let [;; How long entire (profile) body took
@ -56,7 +62,7 @@
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")
pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n")
s-pattern (.replace pattern \d \s)
perc #(Math/round (/ %1 %2 0.01))
@ -70,19 +76,18 @@
:else (str (long nanosecs) "ns"))))]
(with-out-str
(printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total")
(printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Total%" "Total")
(doseq [pname (->> (keys stats)
(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)
(perc total total-time)
(ft total))))
(let [{:keys [count min max mean mad total]} (stats pname)]
(printf pattern (fqname pname) count (ft min) (ft max) (ft mad)
(ft mean) (perc total total-time) (ft total))))
(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)))))))
(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
@ -111,7 +116,7 @@
(fn [name# stats#]
(timbre/log* ~level
{:profile-stats stats#}
(str "Profiling: " (fqname name#))
(str "Profiling " (fqname name#))
(str "\n" (plog-table stats#))))
~name
(p :meta/total ~@body))