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

Merge branch 'dev'

This commit is contained in:
Peter Taoussanis 2013-02-08 14:22:18 +07:00
parent b0738b73b4 766a3d61b0
commit b3b109b08a
4 changed files with 68 additions and 57 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
README.md
View File

@ -1,7 +1,7 @@
Current [semantic](http://semver.org/) version:
```clojure
[com.taoensso/timbre "1.5.0"]
[com.taoensso/timbre "1.5.1"]
```
# Timbre, a (sane) Clojure logging & profiling library
@ -27,7 +27,7 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin
Depend on Timbre in your `project.clj`:
```clojure
[com.taoensso/timbre "1.5.0"]
[com.taoensso/timbre "1.5.1"]
```
and `use` the library:

2
project.clj
View File

@ -1,4 +1,4 @@
(defproject com.taoensso/timbre "1.5.0"
(defproject com.taoensso/timbre "1.5.1"
:description "Clojure logging & profiling library"
:url "https://github.com/ptaoussanis/timbre"
:license {:name "Eclipse Public License"}

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

@ -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
@ -61,11 +68,12 @@
sorted-fvs (sorted-fvals form-stats)]
(str fname " "
(str/join " "
(mapv (fn [v] (vector v (get form-stats v 0)))
sorted-fvs))))))))
;; TODO mapv Clojure 1.4+
(vec (map (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

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

@ -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 <min-time> ...} ...}"
"{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}
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