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

Profiling housekeeping, add `pspy*` fn

This commit is contained in:
Peter Taoussanis 2014-02-23 20:00:02 +07:00
parent 7355cd6424
commit f879882e8f
3 changed files with 54 additions and 45 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
README.md
View File

@ -42,7 +42,7 @@ The `refer-timbre` call is a convenience fn that executes:
:refer (log trace debug info warn error fatal report
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level sometimes)])
(require '[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)])
(require '[taoensso.timbre.profiling :as profiling :refer (pspy pspy* profile defnp)])
```
### Logging

4
src/taoensso/timbre.clj
View File

@ -507,7 +507,7 @@
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level sometimes)])
(require
'[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)])"
'[taoensso.timbre.profiling :as profiling :refer (pspy pspy* profile defnp)])"
[]
(require
'[taoensso.timbre :as timbre
@ -515,7 +515,7 @@
logf tracef debugf infof warnf errorf fatalf reportf
spy logged-future with-log-level sometimes)])
(require
'[taoensso.timbre.profiling :as profiling :refer (pspy profile defnp)]))
'[taoensso.timbre.profiling :as profiling :refer (pspy pspy* profile defnp)]))
;;;; Deprecated

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

@ -5,21 +5,30 @@
[taoensso.encore :as encore]
[taoensso.timbre :as timbre]))
(def ^:dynamic *pdata* "{::pname [time1 time2 ...]}" nil)
(defmacro fq-keyword "Returns namespaced keyword for given id."
[id]
`(if (and (keyword? ~id) (namespace ~id)) ~id
(keyword (str ~*ns*) (name ~id))))
(comment (map #(fq-keyword %) ["foo" :foo :foo/bar]))
(def ^:dynamic *pdata* "{::pid [time1 time2 ...]}" nil)
(defn pspy* [id f]
(if-not *pdata* (f)
(let [id (fq-keyword id)
t0 (System/nanoTime)]
(try (f)
(finally
(let [t-elapsed (- (System/nanoTime) t0)]
(swap! *pdata* #(assoc % id (conj (% id []) t-elapsed)))))))))
(defmacro pspy
"Profile spy. When in the context of a *pdata* binding, records execution time
of named body. Always returns the body's result."
[name & body]
`(if-not *pdata* (do ~@body)
(let [name# (encore/fq-keyword ~name)
start-time# (System/nanoTime)]
(try (do ~@body)
(finally
(let [elapsed# (- (System/nanoTime) start-time#)]
(swap! *pdata* #(assoc % name# (conj (% name# []) elapsed#)))))))))
[id & body] `(pspy* ~id (fn [] ~@body)))
(defmacro p [name & body] `(pspy ~name ~@body)) ; Alias
(defmacro p [id & body] `(pspy ~id ~@body)) ; Alias
(declare pdata-stats format-pdata)
@ -38,66 +47,66 @@
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]
[level id & body]
`(let [{result# :result stats# :stats} (with-pdata ~level ~@body)]
(when stats#
(timbre/log* {:profile-stats stats#} :format ~level
"Profiling: %s\n%s" (encore/fq-keyword ~name)
"Profiling: %s\n%s" (fq-keyword ~id)
(format-pdata stats#)))
result#))
(defmacro sampling-profile
"Like `profile`, but only enables profiling with given probability."
[level probability name & body]
[level probability id & body]
`(do (assert (<= 0 ~probability 1) "Probability: 0<=p<=1")
(if-not (< (rand) ~probability) (do ~@body)
(profile ~level ~name ~@body))))
(profile ~level ~id ~@body))))
(defn pdata-stats
"{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}
"{::pid [time1 time2 ...] ...} => {::pid {:min <min-time> ...} ...}
For performance, stats are calculated once only after all data have been
collected."
[pdata]
(reduce-kv
(fn [m pname times]
(fn [m pid times]
(let [count (max 1 (count times))
time (reduce + times)
mean (long (/ time count))
mad (long (/ (reduce + (map #(Math/abs (long (- % mean)))
times)) ; Mean absolute deviation
count))]
(assoc m pname {:count count
:min (apply min times)
:max (apply max times)
:mean mean
:mad mad
:time time})))
(assoc m pid {:count count
:min (apply min times)
:max (apply max times)
:mean mean
:mad mad
:time time})))
{} (or pdata {})))
(defn format-pdata [stats & [sort-field]]
(let [clock-time (-> stats ::clock-time :time) ; How long entire profile body took
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")
stats (dissoc stats ::clock-time)
accounted (reduce + (map :time (vals stats)))
max-id-width (apply max (map (comp count str)
(conj (keys stats) "Accounted Time")))
pattern (str "%" max-id-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 #(encore/round %2 :round (/ nanosecs (pow %1)))]
to-pow #(encore/round (/ nanosecs (pow %1)) :round %2)]
(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")
(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)
(printf s-pattern "Id" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time")
(doseq [pid (->> (keys stats)
(sort-by #(- (get-in stats [% (or sort-field :time)]))))]
(let [{:keys [count min max mean mad time]} (stats pid)]
(printf pattern pid count (ft min) (ft max) (ft mad)
(ft mean) (perc time clock-time) (ft time))))
(printf s-pattern "Clock Time" "" "" "" "" "" 100 (ft clock-time))
@ -107,7 +116,7 @@
(defmacro defnp "Like `defn` but wraps body in `p` macro."
{:arglists '([name ?doc-string ?attr-map [params] ?prepost-map body])}
[name & sigs]
(let [[name [params & sigs]] (macro/name-with-attributes name sigs)
(let [[name [params & sigs]] (encore/name-with-attrs name sigs)
prepost-map (when (and (map? (first sigs)) (next sigs)) (first sigs))
body (if prepost-map (next sigs) sigs)]
`(defn ~name ~params ~prepost-map
@ -120,14 +129,14 @@
(comment
(profile :info :sleepy-threads
(dotimes [n 5]
(Thread/sleep 100) ; Unaccounted
(p :1ms (Thread/sleep 1))
(p :2s (Thread/sleep 2000))
(p :50ms (Thread/sleep 50))
(p :rand (Thread/sleep (if (> 0.5 (rand)) 10 500)))
(p :10ms (Thread/sleep 10))
"Result"))
(dotimes [n 5]
(Thread/sleep 100) ; Unaccounted
(p :1ms (Thread/sleep 1))
(p :2s (Thread/sleep 2000))
(p :50ms (Thread/sleep 50))
(p :rand (Thread/sleep (if (> 0.5 (rand)) 10 500)))
(p :10ms (Thread/sleep 10))
"Result"))
(p :hello "Hello, this is a result") ; Falls through (no *pdata* context)