From ff5ce760cfb8cc8810f30b8b1f6e7c98a4c84264 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Thu, 7 Feb 2013 20:27:17 +0700 Subject: [PATCH] Housekeeping --- src/taoensso/timbre/frequencies.clj | 27 +++++---- src/taoensso/timbre/profiling.clj | 87 +++++++++++++++-------------- 2 files changed, 62 insertions(+), 52 deletions(-) diff --git a/src/taoensso/timbre/frequencies.clj b/src/taoensso/timbre/frequencies.clj index 67154ae..1711db0 100644 --- a/src/taoensso/timbre/frequencies.clj +++ b/src/taoensso/timbre/frequencies.clj @@ -7,8 +7,6 @@ (def ^:dynamic *fdata* "{::fname {form-value frequency}}" nil) -(declare fdata-table) - (defmacro with-fdata [level & body] `(if-not (timbre/logging-enabled? ~level) @@ -16,13 +14,15 @@ (binding [*fdata* (atom {})] {:result (do ~@body) :stats @*fdata*}))) +(declare format-fdata) + (defmacro log-frequencies "When logging is enabled, executes named body with frequency counting enabled. Body forms wrapped in (fspy) will have their result frequencies logged. Always returns body's result. - Note that logging appenders will receive both a frequencies table string AND - the raw frequency stats under a special :frequency-stats key (useful for + Note that logging appenders will receive both a formatted frequencies string + AND the raw frequency stats under a special :frequency-stats key (useful for queryable db logging)." [level name & body] (let [name (utils/fq-keyword name)] @@ -31,9 +31,17 @@ (timbre/log* ~level {:frequency-stats stats#} (str "Frequencies " ~name) - (str "\n" (fdata-table stats#)))) + (str "\n" (format-fdata stats#)))) result#))) +(defmacro sampling-log-frequencies + "Like `log-frequencies`, but only enables frequency counting every + 1/`proportion` calls. Always returns body's result." + [level proportion name & body] + `(if-not (> ~proportion (rand)) + (do ~@body) + (log-frequencies ~level ~name ~@body))) + (defmacro fspy "Frequency spy. When in the context of a *fdata* binding, records the frequency of each enumerated result. Always returns the body's result." @@ -44,13 +52,12 @@ (let [name# ~name result# (do ~@body)] (swap! *fdata* #(assoc-in % [name# result#] - (inc (get-in % [name# result#] 0)))) + (inc (get-in % [name# result#] 0)))) result#)))) (defmacro f [name & body] `(fspy name ~@body)) ; Alias -(defn fdata-table - "Returns formatted table string for given fdata stats." +(defn format-fdata [stats] (let [sorted-fnames (sort (keys stats)) sorted-fvals (fn [form-stats] (reverse (sort-by form-stats @@ -64,8 +71,8 @@ (mapv (fn [v] (vector v (get form-stats v 0))) sorted-fvs)))))))) -(comment (fdata-table {:name1 {:a 10 :b 4 :c 20} - :name2 {33 8 12 2 false 6}})) +(comment (format-fdata {:name1 {:a 10 :b 4 :c 20} + :name2 {33 8 12 2 false 6}})) (comment (with-fdata :info diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index 20a10b0..80e57dc 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -4,9 +4,9 @@ (:require [taoensso.timbre :as timbre] [taoensso.timbre.utils :as utils])) -(def ^:dynamic *pdata* "{::pname [time1 time2 ...] ...}" nil) +(def ^:dynamic *pdata* "{::pname [time1 time2 ...]}" nil) -(declare p pdata-stats pdata-table) +(declare p) (defmacro with-pdata [level & body] @@ -15,14 +15,16 @@ (binding [*pdata* (atom {})] {:result (p ::clock-time ~@body) :stats (pdata-stats @*pdata*)}))) +(declare pdata-stats format-pdata) + (defmacro profile "When logging is enabled, executes named body with profiling enabled. Body forms wrapped in (pspy) will be timed and time stats logged. Always returns body's result. - Note that logging appenders will receive both a profiling table string AND the - raw profiling stats under a special :profiling-stats key (useful for queryable - db logging)." + Note that logging appenders will receive both a formatted profiling string AND + the raw profiling stats under a special :profiling-stats key (useful for + queryable db logging)." [level name & body] (let [name (utils/fq-keyword name)] `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)] @@ -30,7 +32,7 @@ (timbre/log* ~level {:profile-stats stats#} (str "Profiling " ~name) - (str "\n" (pdata-table stats#)))) + (str "\n" (format-pdata stats#)))) result#))) (defmacro sampling-profile @@ -48,24 +50,27 @@ (let [name (utils/fq-keyword name)] `(if-not *pdata* (do ~@body) - (let [start-time# (System/nanoTime) + (let [name# ~name + start-time# (System/nanoTime) result# (do ~@body) elapsed# (- (System/nanoTime) start-time#)] - (swap! *pdata* #(assoc % ~name (conj (% ~name []) elapsed#))) + (swap! *pdata* #(assoc % name# (conj (% name# []) elapsed#))) result#)))) (defmacro p [name & body] `(pspy ~name ~@body)) ; Alias (defn pdata-stats - "{::pname [time1 time2 ...] ...} => {::pname {:min ...} ...}" + "{::pname [time1 time2 ...] ...} => {::pname {:min ...} ...} + + For performance, stats are calculated once only after all data have been + collected." [pdata] (reduce (fn [m [pname times]] ; TODO reduce-kv for Clojure 1.4+ (let [count (count times) time (reduce + times) mean (long (/ time count)) - ;; Mean Absolute Deviation mad (long (/ (reduce + (map #(Math/abs (long (- % mean))) - times)) + times)) ; Mean absolute deviation count))] (assoc m pname {:count count :min (apply min times) @@ -75,42 +80,40 @@ :time time}))) {} pdata)) -(defn pdata-table - "Returns formatted table string for given pdata stats." - ([stats] (pdata-table stats :time)) - ([stats sort-field] - (let [;; How long entire (profile) body took - clock-time (-> stats ::clock-time :time) - stats (dissoc stats ::clock-time) +(defn format-pdata + [stats & [sort-field]] + (let [;; How long entire (profile) body took + clock-time (-> stats ::clock-time :time) + stats (dissoc stats ::clock-time) - accounted (reduce + (map :time (vals stats))) - max-name-width (apply max (map (comp count str) - (conj (keys stats) "Accounted Time"))) - pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n") - s-pattern (.replace pattern \d \s) + accounted (reduce + (map :time (vals stats))) + max-name-width (apply max (map (comp count str) + (conj (keys stats) "Accounted Time"))) + 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)) - ft (fn [nanosecs] - (let [pow #(Math/pow 10 %) - ok-pow? #(>= nanosecs (pow %)) - to-pow #(utils/round-to %2 (/ nanosecs (pow %1)))] - (cond (ok-pow? 9) (str (to-pow 9 1) "s") - (ok-pow? 6) (str (to-pow 6 0) "ms") - (ok-pow? 3) (str (to-pow 3 0) "μs") - :else (str nanosecs "ns"))))] + perc #(Math/round (/ %1 %2 0.01)) + ft (fn [nanosecs] + (let [pow #(Math/pow 10 %) + ok-pow? #(>= nanosecs (pow %)) + to-pow #(utils/round-to %2 (/ nanosecs (pow %1)))] + (cond (ok-pow? 9) (str (to-pow 9 1) "s") + (ok-pow? 6) (str (to-pow 6 0) "ms") + (ok-pow? 3) (str (to-pow 3 0) "μs") + :else (str nanosecs "ns"))))] - (with-out-str - (printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time") + (with-out-str + (printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time") - (doseq [pname (->> (keys stats) - (sort-by #(- (get-in stats [% sort-field]))))] - (let [{:keys [count min max mean mad time]} (stats pname)] - (printf pattern pname count (ft min) (ft max) (ft mad) - (ft mean) (perc time clock-time) (ft time)))) + (doseq [pname (->> (keys stats) + (sort-by #(- (get-in stats [% (or sort-field :time)]))))] + (let [{:keys [count min max mean mad time]} (stats pname)] + (printf pattern pname count (ft min) (ft max) (ft mad) + (ft mean) (perc time clock-time) (ft time)))) - (printf s-pattern "[Clock] Time" "" "" "" "" "" 100 (ft clock-time)) - (printf s-pattern "Accounted Time" "" "" "" "" "" - (perc accounted clock-time) (ft accounted)))))) + (printf s-pattern "[Clock] Time" "" "" "" "" "" 100 (ft clock-time)) + (printf s-pattern "Accounted Time" "" "" "" "" "" + (perc accounted clock-time) (ft accounted))))) (comment (profile :info :Sleepy-threads