From 19f7b898e39ff594972e91182ff083a581c6ed1b Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Wed, 4 Jul 2012 13:47:21 +0700 Subject: [PATCH] Added Mean Absolute Deviation (MAD) times to profiling output. Misc housekeeping. --- README.md | 24 ++++++++++++------------ src/taoensso/timbre.clj | 2 +- src/taoensso/timbre/profiling.clj | 29 +++++++++++++++++------------ 3 files changed, 30 insertions(+), 25 deletions(-) diff --git a/README.md b/README.md index 7df90a6..3580bdb 100644 --- a/README.md +++ b/README.md @@ -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 diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index c396353..8248254 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -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!) diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index 8c9ef5c..1ccdf00 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -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))