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

Housekeeping

This commit is contained in:
Peter Taoussanis 2013-02-07 20:27:17 +07:00
parent b0738b73b4
commit ff5ce760cf
2 changed files with 62 additions and 52 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

27
src/taoensso/timbre/frequencies.clj
View File

@ -7,8 +7,6 @@
(def ^:dynamic *fdata* "{::fname {form-value frequency}}" nil) (def ^:dynamic *fdata* "{::fname {form-value frequency}}" nil)
(declare fdata-table)
(defmacro with-fdata (defmacro with-fdata
[level & body] [level & body]
`(if-not (timbre/logging-enabled? ~level) `(if-not (timbre/logging-enabled? ~level)
@ -16,13 +14,15 @@
(binding [*fdata* (atom {})] (binding [*fdata* (atom {})]
{:result (do ~@body) :stats @*fdata*}))) {:result (do ~@body) :stats @*fdata*})))
(declare format-fdata)
(defmacro log-frequencies (defmacro log-frequencies
"When logging is enabled, executes named body with frequency counting enabled. "When logging is enabled, executes named body with frequency counting enabled.
Body forms wrapped in (fspy) will have their result frequencies logged. Always Body forms wrapped in (fspy) will have their result frequencies logged. Always
returns body's result. returns body's result.
Note that logging appenders will receive both a frequencies table string AND Note that logging appenders will receive both a formatted frequencies string
the raw frequency stats under a special :frequency-stats key (useful for AND the raw frequency stats under a special :frequency-stats key (useful for
queryable db logging)." queryable db logging)."
[level name & body] [level name & body]
(let [name (utils/fq-keyword name)] (let [name (utils/fq-keyword name)]
@ -31,9 +31,17 @@
(timbre/log* ~level (timbre/log* ~level
{:frequency-stats stats#} {:frequency-stats stats#}
(str "Frequencies " ~name) (str "Frequencies " ~name)
(str "\n" (fdata-table stats#)))) (str "\n" (format-fdata stats#))))
result#))) 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 (defmacro fspy
"Frequency spy. When in the context of a *fdata* binding, records the frequency "Frequency spy. When in the context of a *fdata* binding, records the frequency
of each enumerated result. Always returns the body's result." of each enumerated result. Always returns the body's result."
@ -44,13 +52,12 @@
(let [name# ~name (let [name# ~name
result# (do ~@body)] result# (do ~@body)]
(swap! *fdata* #(assoc-in % [name# result#] (swap! *fdata* #(assoc-in % [name# result#]
(inc (get-in % [name# result#] 0)))) (inc (get-in % [name# result#] 0))))
result#)))) result#))))
(defmacro f [name & body] `(fspy name ~@body)) ; Alias (defmacro f [name & body] `(fspy name ~@body)) ; Alias
(defn fdata-table (defn format-fdata
"Returns formatted table string for given fdata stats."
[stats] [stats]
(let [sorted-fnames (sort (keys stats)) (let [sorted-fnames (sort (keys stats))
sorted-fvals (fn [form-stats] (reverse (sort-by form-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))) (mapv (fn [v] (vector v (get form-stats v 0)))
sorted-fvs)))))))) sorted-fvs))))))))
(comment (fdata-table {:name1 {:a 10 :b 4 :c 20} (comment (format-fdata {:name1 {:a 10 :b 4 :c 20}
:name2 {33 8 12 2 false 6}})) :name2 {33 8 12 2 false 6}}))
(comment (comment
(with-fdata :info (with-fdata :info

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

@ -4,9 +4,9 @@
(:require [taoensso.timbre :as timbre] (:require [taoensso.timbre :as timbre]
[taoensso.timbre.utils :as utils])) [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 (defmacro with-pdata
[level & body] [level & body]
@ -15,14 +15,16 @@
(binding [*pdata* (atom {})] (binding [*pdata* (atom {})]
{:result (p ::clock-time ~@body) :stats (pdata-stats @*pdata*)}))) {:result (p ::clock-time ~@body) :stats (pdata-stats @*pdata*)})))
(declare pdata-stats format-pdata)
(defmacro profile (defmacro profile
"When logging is enabled, executes named body with profiling enabled. Body "When logging is enabled, executes named body with profiling enabled. Body
forms wrapped in (pspy) will be timed and time stats logged. Always returns forms wrapped in (pspy) will be timed and time stats logged. Always returns
body's result. body's result.
Note that logging appenders will receive both a profiling table string AND the Note that logging appenders will receive both a formatted profiling string AND
raw profiling stats under a special :profiling-stats key (useful for queryable the raw profiling stats under a special :profiling-stats key (useful for
db logging)." queryable db logging)."
[level name & body] [level name & body]
(let [name (utils/fq-keyword name)] (let [name (utils/fq-keyword name)]
`(let [{result# :result stats# :stats} (with-pdata ~level ~@body)] `(let [{result# :result stats# :stats} (with-pdata ~level ~@body)]
@ -30,7 +32,7 @@
(timbre/log* ~level (timbre/log* ~level
{:profile-stats stats#} {:profile-stats stats#}
(str "Profiling " ~name) (str "Profiling " ~name)
(str "\n" (pdata-table stats#)))) (str "\n" (format-pdata stats#))))
result#))) result#)))
(defmacro sampling-profile (defmacro sampling-profile
@ -48,24 +50,27 @@
(let [name (utils/fq-keyword name)] (let [name (utils/fq-keyword name)]
`(if-not *pdata* `(if-not *pdata*
(do ~@body) (do ~@body)
(let [start-time# (System/nanoTime) (let [name# ~name
start-time# (System/nanoTime)
result# (do ~@body) result# (do ~@body)
elapsed# (- (System/nanoTime) start-time#)] elapsed# (- (System/nanoTime) start-time#)]
(swap! *pdata* #(assoc % ~name (conj (% ~name []) elapsed#))) (swap! *pdata* #(assoc % name# (conj (% name# []) elapsed#)))
result#)))) result#))))
(defmacro p [name & body] `(pspy ~name ~@body)) ; Alias (defmacro p [name & body] `(pspy ~name ~@body)) ; Alias
(defn pdata-stats (defn pdata-stats
"{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}" "{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}
For performance, stats are calculated once only after all data have been
collected."
[pdata] [pdata]
(reduce (fn [m [pname times]] ; TODO reduce-kv for Clojure 1.4+ (reduce (fn [m [pname times]] ; TODO reduce-kv for Clojure 1.4+
(let [count (count times) (let [count (count times)
time (reduce + times) time (reduce + times)
mean (long (/ time count)) mean (long (/ time count))
;; Mean Absolute Deviation
mad (long (/ (reduce + (map #(Math/abs (long (- % mean))) mad (long (/ (reduce + (map #(Math/abs (long (- % mean)))
times)) times)) ; Mean absolute deviation
count))] count))]
(assoc m pname {:count count (assoc m pname {:count count
:min (apply min times) :min (apply min times)
@ -75,42 +80,40 @@
:time time}))) :time time})))
{} pdata)) {} pdata))
(defn pdata-table (defn format-pdata
"Returns formatted table string for given pdata stats." [stats & [sort-field]]
([stats] (pdata-table stats :time)) (let [;; How long entire (profile) body took
([stats sort-field] clock-time (-> stats ::clock-time :time)
(let [;; How long entire (profile) body took stats (dissoc stats ::clock-time)
clock-time (-> stats ::clock-time :time)
stats (dissoc stats ::clock-time)
accounted (reduce + (map :time (vals stats))) accounted (reduce + (map :time (vals stats)))
max-name-width (apply max (map (comp count str) max-name-width (apply max (map (comp count str)
(conj (keys stats) "Accounted Time"))) (conj (keys stats) "Accounted Time")))
pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n") pattern (str "%" max-name-width "s %6d %9s %10s %9s %9s %7d %1s%n")
s-pattern (.replace pattern \d \s) s-pattern (.replace pattern \d \s)
perc #(Math/round (/ %1 %2 0.01)) perc #(Math/round (/ %1 %2 0.01))
ft (fn [nanosecs] ft (fn [nanosecs]
(let [pow #(Math/pow 10 %) (let [pow #(Math/pow 10 %)
ok-pow? #(>= nanosecs (pow %)) ok-pow? #(>= nanosecs (pow %))
to-pow #(utils/round-to %2 (/ nanosecs (pow %1)))] to-pow #(utils/round-to %2 (/ nanosecs (pow %1)))]
(cond (ok-pow? 9) (str (to-pow 9 1) "s") (cond (ok-pow? 9) (str (to-pow 9 1) "s")
(ok-pow? 6) (str (to-pow 6 0) "ms") (ok-pow? 6) (str (to-pow 6 0) "ms")
(ok-pow? 3) (str (to-pow 3 0) "μs") (ok-pow? 3) (str (to-pow 3 0) "μs")
:else (str nanosecs "ns"))))] :else (str nanosecs "ns"))))]
(with-out-str (with-out-str
(printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time") (printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time")
(doseq [pname (->> (keys stats) (doseq [pname (->> (keys stats)
(sort-by #(- (get-in stats [% sort-field]))))] (sort-by #(- (get-in stats [% (or sort-field :time)]))))]
(let [{:keys [count min max mean mad time]} (stats pname)] (let [{:keys [count min max mean mad time]} (stats pname)]
(printf pattern pname count (ft min) (ft max) (ft mad) (printf pattern pname count (ft min) (ft max) (ft mad)
(ft mean) (perc time clock-time) (ft time)))) (ft mean) (perc time clock-time) (ft time))))
(printf s-pattern "[Clock] Time" "" "" "" "" "" 100 (ft clock-time)) (printf s-pattern "[Clock] Time" "" "" "" "" "" 100 (ft clock-time))
(printf s-pattern "Accounted Time" "" "" "" "" "" (printf s-pattern "Accounted Time" "" "" "" "" ""
(perc accounted clock-time) (ft accounted)))))) (perc accounted clock-time) (ft accounted)))))
(comment (comment
(profile :info :Sleepy-threads (profile :info :Sleepy-threads