mirror of https://github.com/status-im/timbre.git
Merge branch 'dev'
This commit is contained in:
Peter Taoussanis
commit
7ce22499c7
|
|
@ -1,3 +1,11 @@
|
|||
## Pending / unreleased
|
||||
|
||||
* [#60] **FIX**: `defnp` no longer generates an Eastwood warning (@ducky427).
|
||||
* **CHANGE**: Improved profiling memory efficiency (max memory use, was previously unbounded).
|
||||
* **CHANGE**: Profiling: make larger call numbers easier to read.
|
||||
* [#63]: **NEW**: Add support for thread-local configuration (@jameswarren).
|
||||
|
||||
|
||||
## v3.1.6 / 2014 Mar 16
|
||||
|
||||
* [#56] FIX: `defnp`/`p` head retention issue (kyptin).
|
||||
|
|
|
|||
15
README.md
15
README.md
|
|
@ -1,12 +1,10 @@
|
|||
**[API docs][]** | **[CHANGELOG][]** | [other Clojure libs][] | [Twitter][] | [contact/contributing](#contact--contributing) | current ([semantic][]) version:
|
||||
|
||||
```clojure
|
||||
[com.taoensso/timbre "3.1.6"] ; Stable
|
||||
[com.taoensso/timbre "3.2.0"] ; Stable
|
||||
```
|
||||
|
||||
v3 is a **major, backwards-compatible release**. Please see the [CHANGELOG][] for details.
|
||||
|
||||
Appender authors: please see [here](https://github.com/ptaoussanis/timbre/issues/41) about migrating Timbre 2.x appenders to 3.x's recommended style.
|
||||
v3 is a **major, backwards-compatible release**. Please see the [CHANGELOG][] for details. Appender authors: please see [here](https://github.com/ptaoussanis/timbre/issues/41) about migrating Timbre 2.x appenders to 3.x's recommended style.
|
||||
|
||||
# Timbre, a (sane) Clojure logging & profiling library
|
||||
|
||||
|
|
@ -25,6 +23,10 @@ Logging with Java can be maddeningly, unnecessarily hard. Particularly if all yo
|
|||
* [tools.logging](https://github.com/clojure/tools.logging) support (optional, useful when integrating with legacy logging systems).
|
||||
* Dead-simple, logging-level-aware **logging profiler**.
|
||||
|
||||
## 3rd-party tools, appenders, etc.
|
||||
* [log-config](https://github.com/palletops/log-config) by [Hugo Duncan](https://github.com/hugoduncan) - library to help manage Timbre logging config.
|
||||
* Suggestions welcome!
|
||||
|
||||
## Getting started
|
||||
|
||||
### Dependencies
|
||||
|
|
@ -32,7 +34,7 @@ Logging with Java can be maddeningly, unnecessarily hard. Particularly if all yo
|
|||
Add the necessary dependency to your [Leiningen][] `project.clj` and use the supplied ns-import helper:
|
||||
|
||||
```clojure
|
||||
[com.taoensso/timbre "3.1.6"] ; project.clj
|
||||
[com.taoensso/timbre "3.2.0"] ; project.clj
|
||||
|
||||
(ns my-app (:require [taoensso.timbre :as timbre])) ; Your ns
|
||||
(timbre/refer-timbre) ; Provides useful Timbre aliases in this ns
|
||||
|
|
@ -43,7 +45,8 @@ The `refer-timbre` call is a convenience fn that executes:
|
|||
(require '[taoensso.timbre :as timbre
|
||||
:refer (log trace debug info warn error fatal report
|
||||
logf tracef debugf infof warnf errorf fatalf reportf
|
||||
spy logged-future with-log-level sometimes)])
|
||||
spy logged-future with-log-level with-logging-config
|
||||
sometimes)])
|
||||
(require '[taoensso.timbre.profiling :as profiling
|
||||
:refer (pspy pspy* profile defnp p p*)])
|
||||
```
|
||||
|
|
|
|||
10
project.clj
10
project.clj
|
|
@ -1,4 +1,4 @@
|
|||
(defproject com.taoensso/timbre "3.1.6"
|
||||
(defproject com.taoensso/timbre "3.2.0"
|
||||
:author "Peter Taoussanis <https://www.taoensso.com>"
|
||||
:description "Clojure logging & profiling library"
|
||||
:url "https://github.com/ptaoussanis/timbre"
|
||||
|
|
@ -11,18 +11,18 @@
|
|||
*assert* true}
|
||||
:dependencies
|
||||
[[org.clojure/clojure "1.4.0"]
|
||||
[com.taoensso/encore "0.9.8"]
|
||||
[com.taoensso/encore "1.5.0"]
|
||||
[io.aviso/pretty "0.1.10"]]
|
||||
|
||||
:test-paths ["test" "src"]
|
||||
:profiles
|
||||
{;; :default [:base :system :user :provided :dev]
|
||||
:1.5 {:dependencies [[org.clojure/clojure "1.5.1"]]}
|
||||
:1.6 {:dependencies [[org.clojure/clojure "1.6.0-beta1"]]}
|
||||
:1.6 {:dependencies [[org.clojure/clojure "1.6.0"]]}
|
||||
:test {:dependencies [[expectations "1.4.56"]
|
||||
[org.clojure/test.check "0.5.7"]
|
||||
[com.taoensso/nippy "2.5.2"]
|
||||
[com.taoensso/carmine "2.4.6"]
|
||||
[com.taoensso/nippy "2.6.3"]
|
||||
[com.taoensso/carmine "2.6.2"]
|
||||
[com.draines/postal "1.11.1"]
|
||||
[org.clojure/tools.logging "0.2.6"]]
|
||||
:plugins [[lein-expectations "0.0.8"]
|
||||
|
|
|
|||
|
|
@ -250,13 +250,12 @@
|
|||
(def ^:private get-hostname
|
||||
(encore/memoize* 60000
|
||||
(fn []
|
||||
(let [p (promise)]
|
||||
(future ; Android doesn't like this on the main thread
|
||||
(deliver p
|
||||
(try (.. java.net.InetAddress getLocalHost getHostName)
|
||||
(catch java.net.UnknownHostException _
|
||||
"UnknownHost"))))
|
||||
@p))))
|
||||
(->
|
||||
(future ; Android doesn't like this on the main thread
|
||||
(try (.. java.net.InetAddress getLocalHost getHostName)
|
||||
(catch java.net.UnknownHostException _
|
||||
"UnknownHost")))
|
||||
(deref 5000 "UnknownHost")))))
|
||||
|
||||
(defn- wrap-appender-juxt
|
||||
"Wraps compile-time appender juxt with additional runtime capabilities
|
||||
|
|
@ -366,11 +365,18 @@
|
|||
|
||||
;;;; Logging macros
|
||||
|
||||
(def ^:dynamic *config-dynamic* nil)
|
||||
(defmacro with-logging-config
|
||||
"Allows thread-local logging config override. Useful for dev & testing."
|
||||
[config & body] `(binding [*config-dynamic* ~config] ~@body))
|
||||
|
||||
(defn get-default-config [] (or *config-dynamic* @config))
|
||||
|
||||
(defn ns-unfiltered? [config ns] ((:ns-filter (compile-config config)) ns))
|
||||
|
||||
(defn logging-enabled? "For 3rd-party utils, etc."
|
||||
[level & [compile-time-ns]]
|
||||
(let [config' @config]
|
||||
(let [config' (get-default-config)]
|
||||
(and (level-sufficient? level config')
|
||||
(or (nil? compile-time-ns)
|
||||
(ns-unfiltered? config' compile-time-ns)))))
|
||||
|
|
@ -380,7 +386,7 @@
|
|||
level base-appender-args log-vargs ns throwable message
|
||||
;; Additional args provided by Timbre only:
|
||||
& [juxt-fn msg-type file line]]
|
||||
(when-let [juxt-fn (or juxt-fn (get-in (compile-config @config)
|
||||
(when-let [juxt-fn (or juxt-fn (get-in (compile-config (get-default-config))
|
||||
[:appenders-juxt level]))]
|
||||
(juxt-fn
|
||||
(conj (or base-appender-args {})
|
||||
|
|
@ -412,8 +418,8 @@
|
|||
`(let [;;; Support [level & log-args], [config level & log-args] sigs:
|
||||
s1# ~s1
|
||||
default-config?# (levels-scored s1#)
|
||||
config# (if default-config?# @config s1#)
|
||||
level# (if default-config?# s1# ~s2)
|
||||
config# (if default-config?# (get-default-config) s1#)
|
||||
level# (if default-config?# s1# ~s2)
|
||||
compile-time-ns# ~(str *ns*)]
|
||||
;; (println "DEBUG: Runtime level check")
|
||||
(when (and (level-sufficient? level# config#)
|
||||
|
|
@ -495,7 +501,8 @@
|
|||
'[taoensso.timbre :as timbre
|
||||
:refer (log trace debug info warn error fatal report
|
||||
logf tracef debugf infof warnf errorf fatalf reportf
|
||||
spy logged-future with-log-level sometimes)])
|
||||
spy logged-future with-log-level with-logging-config
|
||||
sometimes)])
|
||||
(require
|
||||
'[taoensso.timbre.profiling :as profiling
|
||||
:refer (pspy pspy* profile defnp p p*)])"
|
||||
|
|
@ -504,7 +511,8 @@
|
|||
'[taoensso.timbre :as timbre
|
||||
:refer (log trace debug info warn error fatal report
|
||||
logf tracef debugf infof warnf errorf fatalf reportf
|
||||
spy logged-future with-log-level sometimes)])
|
||||
spy logged-future with-log-level with-logging-config
|
||||
sometimes)])
|
||||
(require
|
||||
'[taoensso.timbre.profiling :as profiling
|
||||
:refer (pspy pspy* profile defnp p p*)]))
|
||||
|
|
|
|||
|
|
@ -4,6 +4,8 @@
|
|||
(:require [taoensso.encore :as encore]
|
||||
[taoensso.timbre :as timbre]))
|
||||
|
||||
;;;; Utils
|
||||
|
||||
(defmacro fq-keyword "Returns namespaced keyword for given id."
|
||||
[id]
|
||||
`(if (and (keyword? ~id) (namespace ~id)) ~id
|
||||
|
|
@ -11,7 +13,17 @@
|
|||
|
||||
(comment (map #(fq-keyword %) ["foo" :foo :foo/bar]))
|
||||
|
||||
(def ^:dynamic *pdata* "{::pid [time1 time2 ...]}" nil)
|
||||
;;;;
|
||||
|
||||
(def ^:dynamic *pdata*
|
||||
"{::pid {:times [t1 t2 ...] ; Times awaiting merge into stats
|
||||
:ntimes _ ; (count times)
|
||||
:stats {} ; Cumulative stats
|
||||
}}"
|
||||
nil)
|
||||
|
||||
(declare capture-time! merge-times>stats!)
|
||||
|
||||
(defmacro pspy
|
||||
"Profile spy. When in the context of a *pdata* binding, records execution time
|
||||
of named body. Always returns the body's result."
|
||||
|
|
@ -22,9 +34,7 @@
|
|||
(let [id# (fq-keyword ~id)
|
||||
t0# (System/nanoTime)]
|
||||
(try (do ~@body)
|
||||
(finally
|
||||
(let [t-elapsed# (- (System/nanoTime) t0#)]
|
||||
(swap! *pdata* #(assoc % id# (conj (% id# []) t-elapsed#)))))))))
|
||||
(finally (capture-time! id# (- (System/nanoTime) t0#)))))))
|
||||
|
||||
(defmacro p [id & body] `(pspy ~id ~@body)) ; Alias
|
||||
|
||||
|
|
@ -33,9 +43,7 @@
|
|||
(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)))))))))
|
||||
(finally (capture-time! id (- (System/nanoTime) t0)))))))
|
||||
|
||||
(def p* pspy*) ; Alias
|
||||
|
||||
|
|
@ -45,14 +53,14 @@
|
|||
(time (dotimes [_ 1000000] (pspy :foo))) ; ~65ms (^:dynamic bound >= once!)
|
||||
)
|
||||
|
||||
(declare pdata-stats format-pdata)
|
||||
(declare ^:private format-stats)
|
||||
|
||||
(defmacro with-pdata [level & body]
|
||||
`(if-not (timbre/logging-enabled? ~level ~(str *ns*))
|
||||
{:result (do ~@body)}
|
||||
(binding [*pdata* (atom {})]
|
||||
{:result (pspy ::clock-time ~@body)
|
||||
:stats (pdata-stats @*pdata*)})))
|
||||
:stats (merge-times>stats!)})))
|
||||
|
||||
(defmacro profile
|
||||
"When logging is enabled, executes named body with profiling enabled. Body
|
||||
|
|
@ -67,7 +75,7 @@
|
|||
(when stats#
|
||||
(timbre/log* {:profile-stats stats#} :format ~level
|
||||
"Profiling: %s\n%s" (fq-keyword ~id)
|
||||
(format-pdata stats#)))
|
||||
(format-stats stats#)))
|
||||
result#))
|
||||
|
||||
(defmacro sampling-profile
|
||||
|
|
@ -77,35 +85,112 @@
|
|||
(if-not (< (rand) ~probability) (do ~@body)
|
||||
(profile ~level ~id ~@body))))
|
||||
|
||||
(defn pdata-stats
|
||||
"{::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 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 pid {:count count
|
||||
:min (apply min times)
|
||||
:max (apply max times)
|
||||
:mean mean
|
||||
:mad mad
|
||||
:time time})))
|
||||
{} (or pdata {})))
|
||||
(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]] (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
|
||||
(pspy ~(clojure.core/name name)
|
||||
~@body))))
|
||||
|
||||
(defn format-pdata [stats & [sort-field]]
|
||||
(comment (defnp foo "Docstring "[x] "boo" (* x x))
|
||||
(macroexpand '(defnp foo "Docstring "[x] "boo" (* x x)))
|
||||
(profile :info :defnp-test (foo 5)))
|
||||
|
||||
;;;; Data capturing & aggregation
|
||||
|
||||
(def ^:private ^:constant stats-gc-n 111111)
|
||||
|
||||
(defn capture-time! [id t-elapsed]
|
||||
(let [ntimes
|
||||
(->
|
||||
(swap! *pdata*
|
||||
(fn [m]
|
||||
(let [{:as m-id
|
||||
:keys [times ntimes]
|
||||
:or {times [] ntimes 0}} (get m id {})]
|
||||
(assoc m id
|
||||
(assoc m-id :times (conj times t-elapsed)
|
||||
:ntimes (inc ntimes))))))
|
||||
(get-in [id :ntimes]))]
|
||||
(when (= ntimes stats-gc-n) ; Merge to reduce memory footprint
|
||||
;; This is so much slower than `capture-time!` swaps that it gets delayed
|
||||
;; until after entire profiling call completes!:
|
||||
;; (future (merge-times>stats! id)) ; Uses binding conveyance
|
||||
(p :timbre/stats-gc (merge-times>stats! id)))
|
||||
nil))
|
||||
|
||||
(comment
|
||||
(binding [*pdata* (atom {})]
|
||||
(capture-time! :foo 100000)
|
||||
(capture-time! :foo 100000)
|
||||
*pdata*))
|
||||
|
||||
(defn merge-times>stats!
|
||||
([] ; -> {<pid> <merged-stats>}
|
||||
(reduce (fn [m pid] (assoc m pid (merge-times>stats! pid)))
|
||||
{} (keys (or @*pdata* {}))))
|
||||
|
||||
([id] ; -> <merged-stats>
|
||||
(->
|
||||
(swap! *pdata*
|
||||
(fn [m]
|
||||
(let [{:as m-id
|
||||
:keys [times ntimes stats]
|
||||
:or {times []
|
||||
ntimes 0
|
||||
stats {}}} (get m id {})]
|
||||
(if (empty? times) m
|
||||
(let [ts-count (max 1 ntimes)
|
||||
ts-time (reduce + times)
|
||||
ts-mean (/ ts-time ts-count)
|
||||
;; Batched "online" MAD calculation here is >= the standard
|
||||
;; Knuth/Welford method, Ref. http://goo.gl/QLSfOc,
|
||||
;; http://goo.gl/mx5eSK.
|
||||
ts-mad-sum (reduce + (map #(Math/abs (long (- % ts-mean)))
|
||||
times)) ; Mean absolute deviation
|
||||
;;
|
||||
s-count (+ (:count stats 0) ts-count)
|
||||
s-time (+ (:time stats 0) ts-time)
|
||||
s-mean (/ s-time s-count)
|
||||
s-mad-sum (+ (:mad-sum stats 0) ts-mad-sum)
|
||||
s-mad (/ s-mad-sum s-count)
|
||||
s-min (apply min (:min stats Double/POSITIVE_INFINITY) times)
|
||||
s-max (apply max (:max stats 0) times)]
|
||||
(assoc m id
|
||||
(assoc m-id
|
||||
:times []
|
||||
:ntimes 0
|
||||
:stats {:count s-count
|
||||
:min s-min
|
||||
:max s-max
|
||||
:mean s-mean
|
||||
:mad-sum s-mad-sum
|
||||
:mad s-mad
|
||||
:time s-time})))))))
|
||||
(get-in [id :stats]))))
|
||||
|
||||
(comment
|
||||
(binding [*pdata* (atom {})]
|
||||
(capture-time! :foo 10)
|
||||
(capture-time! :foo 20)
|
||||
(merge-times>stats! :foo)
|
||||
(capture-time! :foo 30)
|
||||
(merge-times>stats! :foo)
|
||||
(merge-times>stats! :bar)
|
||||
(capture-time! :foo 10)
|
||||
*pdata*))
|
||||
|
||||
(defn format-stats [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-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)
|
||||
pattern (str "%" max-id-width "s %,11d %9s %10s %9s %9s %7d %1s%n")
|
||||
s-pattern (str "%" max-id-width "s %11s %9s %10s %9s %9s %7s %1s%n")
|
||||
perc #(Math/round (/ %1 %2 0.01))
|
||||
ft (fn [nanosecs]
|
||||
(let [pow #(Math/pow 10 %)
|
||||
|
|
@ -117,7 +202,7 @@
|
|||
:else (str nanosecs "ns"))))]
|
||||
|
||||
(with-out-str
|
||||
(printf s-pattern "Id" "Calls" "Min" "Max" "MAD" "Mean" "Time%" "Time")
|
||||
(printf s-pattern "Id" "nCalls" "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)]
|
||||
|
|
@ -134,7 +219,7 @@
|
|||
(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
|
||||
`(defn ~name ~params ~(or prepost-map {})
|
||||
(pspy ~(clojure.core/name name)
|
||||
~@body))))
|
||||
|
||||
|
|
@ -166,5 +251,12 @@
|
|||
(p :div (reduce / nums)))))
|
||||
|
||||
(profile :info :Arithmetic (dotimes [n 100] (my-fn)))
|
||||
(profile :info :high-n (dotimes [n 1e6] (p :divs (/ 1 2 3 4 5 6 7 8 9))))
|
||||
(let [;; MAD = 154.0ms, natural:
|
||||
;; n->s {0 10 1 100 2 50 3 500 4 8 5 300 6 32 7 433 8 213 9 48}
|
||||
;; MAD = 236.0ms, pathological:
|
||||
n->s {0 10 1 11 2 5 3 18 4 7 5 2 6 300 7 400 8 600 9 700}]
|
||||
(with-redefs [stats-gc-n 3]
|
||||
(profile :info :high-sigma (dotimes [n 10] (p :sleep (Thread/sleep (n->s n)))))))
|
||||
|
||||
(sampling-profile :info 0.2 :sampling-test (p :string "Hello!")))
|
||||
|
|
|
|||
Loading…
Reference in New Issue