status-im/timbre
2
0
Fork 0
mirror of https://github.com/status-im/timbre.git synced 2025-01-29 05:07:07 +00:00
Code Issues Projects Releases Wiki Activity

Merge branch 'dev': v0.6.1.

Browse Source
This commit is contained in:
Peter Taoussanis 2012-07-05 16:48:27 +07:00
commit c1d9442ec2
7 changed files with 48 additions and 45 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

30
README.md
View File

@ -1,7 +1,7 @@
Current version: Current [semantic](http://semver.org/) version:
```clojure ```clojure
[com.taoensso/timbre "0.6.0"] [com.taoensso/timbre "0.6.1"] ; Please note that the repo and ns have changed recently
``` ```
# Timbre, a (sane) logging library for Clojure # Timbre, a (sane) logging library for Clojure
@ -37,7 +37,7 @@ lein2 all test
Depend on Timbre in your `project.clj`: Depend on Timbre in your `project.clj`:
```clojure ```clojure
[com.taoensso/timbre "0.6.0"] [com.taoensso/timbre "0.6.1"]
``` ```
and `use` the library: and `use` the library:
@ -207,23 +207,23 @@ The `profile` macro can now be used to log times for any wrapped forms:
```clojure ```clojure
(profile :info :Arithmetic (dotimes [n 100] (my-fn))) (profile :info :Arithmetic (dotimes [n 100] (my-fn)))
=> "Done!" => "Done!"
%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling: my-app/Arithmetic %> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling my-app/Arithmetic
Name Count Min Max Mean Total% Total Name Calls Min Max MAD Mean Total% Total
my-app/slow-sleep 100 2ms 2ms 2ms 58 232ms my-app/slow-sleep 100 2ms 2ms 31μs 2ms 57 231ms
my-app/fast-sleep 100 1ms 1ms 1ms 30 120ms my-app/fast-sleep 100 1ms 1ms 27μs 1ms 29 118ms
my-app/div 100 65μs 204μs 90μs 2 9ms my-app/add 100 44μs 2ms 46μs 100μs 2 10ms
my-app/add 100 32μs 116μs 59μs 1 5ms my-app/sub 100 42μs 564μs 26μs 72μs 2 7ms
my-app/sub 100 30μs 145μs 47μs 1 4ms my-app/div 100 54μs 191μs 17μs 71μs 2 7ms
my-app/mult 100 33μs 117μs 45μs 1 4ms my-app/mult 100 31μs 165μs 11μs 44μs 1 4ms
Unaccounted 6 25ms Unaccounted 6 26ms
Total 100 403ms Total 100 405ms
``` ```
It's important to note that Timbre profiling is fully **log-level aware**: if the logging level is insufficient, you won't pay for profiling. Likewise, normal namespace filtering applies. (Performance characteristics for both checks are inherited from Timbre itself). It's important to note that Timbre profiling is fully **logging-level aware**: if the level is insufficient, you *won't pay for profiling*. Likewise, normal namespace filtering applies. (Performance characteristics for both checks are inherited from Timbre itself).
And since `p` and `profile` **always return their body's result** regardless of whether profiling actually happens or not, it becomes feasible to use profiling more often as part of your normal workflow: just *leave profiling code in production as you do for logging code*. And since `p` and `profile` **always return their body's result** regardless of whether profiling actually happens or not, it becomes feasible to use profiling more often as part of your normal workflow: just *leave profiling code in production as you do for logging code*.
A **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`. A simple **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`.
## Timbre Supports the ClojureWerkz Project Goals ## Timbre Supports the ClojureWerkz Project Goals

2
project.clj
View File

@ -1,4 +1,4 @@
(defproject com.taoensso/timbre "0.6.0" (defproject com.taoensso/timbre "0.6.1"
:description "Simple, flexible, all-Clojure logging. No XML!" :description "Simple, flexible, all-Clojure logging. No XML!"
:url "https://github.com/ptaoussanis/timbre" :url "https://github.com/ptaoussanis/timbre"
:license {:name "Eclipse Public License"} :license {:name "Eclipse Public License"}

2
src/taoensso/timbre.clj
View File

@ -217,7 +217,7 @@
(not-any? (partial ns-match? ns) ns-blacklist)))))) (not-any? (partial ns-match? ns) ns-blacklist))))))
(reset! ns-filter-cache))) (reset! ns-filter-cache)))
;;; Prime initial caches and recache on config change ;;; Prime initial caches and re-cache on config change
(cache-appenders-juxt!) (cache-appenders-juxt!)
(cache-ns-filter!) (cache-ns-filter!)

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

@ -30,11 +30,17 @@
[plog] [plog]
(reduce (fn [m [pname times]] (reduce (fn [m [pname times]]
(let [count (count times) (let [count (count times)
total (reduce + times)] total (reduce + times)
mean (long (/ total count))
;; Mean Absolute Deviation
mad (long (/ (reduce + (map #(Math/abs (long (- % mean)))
times))
count))]
(assoc m pname {:count count (assoc m pname {:count count
:min (apply min times) :min (apply min times)
:max (apply max times) :max (apply max times)
:mean (long (/ total count)) :mean mean
:mad mad
:total total}))) :total total})))
{} plog)) {} plog))
@ -44,7 +50,7 @@
(str (namespace keyword) "/" (name keyword))) (str (namespace keyword) "/" (name keyword)))
(defn plog-table (defn plog-table
"Returns formatted plog stats table for given plog stats." "Returns formatted table string for given plog stats."
([stats] (plog-table stats :total)) ([stats] (plog-table stats :total))
([stats sort-field] ([stats sort-field]
(let [;; How long entire (profile) body took (let [;; How long entire (profile) body took
@ -56,7 +62,7 @@
max-name-width (apply max (map (comp count str) max-name-width (apply max (map (comp count str)
(conj (keys stats) "Unaccounted"))) (conj (keys stats) "Unaccounted")))
pattern (str "%" max-name-width "s %6d %9s %10s %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))
@ -70,19 +76,18 @@
:else (str (long nanosecs) "ns"))))] :else (str (long nanosecs) "ns"))))]
(with-out-str (with-out-str
(printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total") (printf s-pattern "Name" "Calls" "Min" "Max" "MAD" "Mean" "Total%" "Total")
(doseq [pname (->> (keys stats) (doseq [pname (->> (keys stats)
(sort-by #(- (get-in stats [% sort-field]))))] (sort-by #(- (get-in stats [% sort-field]))))]
(let [{:keys [count min max mean total]} (stats pname)] (let [{:keys [count min max mean mad total]} (stats pname)]
(printf pattern (fqname pname) count (ft min) (ft max) (ft mean) (printf pattern (fqname pname) count (ft min) (ft max) (ft mad)
(perc total total-time) (ft mean) (perc total total-time) (ft total))))
(ft total))))
(let [unacc (- total-time accounted) (let [unacc (- total-time accounted)
unacc-perc (perc unacc total-time)] unacc-perc (perc unacc total-time)]
(printf s-pattern "Unaccounted" "" "" "" "" unacc-perc (ft unacc)) (printf s-pattern "Unaccounted" "" "" "" "" "" unacc-perc (ft unacc))
(printf s-pattern "Total" "" "" "" "" 100 (ft total-time))))))) (printf s-pattern "Total" "" "" "" "" "" 100 (ft total-time)))))))
(defmacro profile* (defmacro profile*
"Executes named body with profiling enabled. Body forms wrapped in (p) will be "Executes named body with profiling enabled. Body forms wrapped in (p) will be
@ -111,7 +116,7 @@
(fn [name# stats#] (fn [name# stats#]
(timbre/log* ~level (timbre/log* ~level
{:profile-stats stats#} {:profile-stats stats#}
(str "Profiling: " (fqname name#)) (str "Profiling " (fqname name#))
(str "\n" (plog-table stats#)))) (str "\n" (plog-table stats#))))
~name ~name
(p :meta/total ~@body)) (p :meta/total ~@body))
@ -127,12 +132,14 @@
(comment (comment
(profile :info :Sleepy-threads (profile :info :Sleepy-threads
(Thread/sleep 100) ; Unaccounted (dotimes [n 5]
(p :1ms (Thread/sleep 1)) (Thread/sleep 100) ; Unaccounted
(p :2s (Thread/sleep 2000)) (p :1ms (Thread/sleep 1))
(p :50ms (Thread/sleep 50)) (p :2s (Thread/sleep 2000))
(p :10ms (Thread/sleep 10)) (p :50ms (Thread/sleep 50))
"Result") (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 *plog* context) (p :hello "Hello, this is a result") ; Falls through (no *plog* context)

6
test/test_taoensso/timbre.clj Normal file
View File

@ -0,0 +1,6 @@
(ns test-taoensso.timbre
(:use [clojure.test]
[taoensso.timbre :as timbre :only (info)]
[taoensso.timbre.profiling :as profiling :only (p profile)]))
(deftest test-nothing) ; TODO

5
test/test_timbre/timbre.clj
View File

@ -1,5 +0,0 @@
(ns test-timbre.timbre
(:use [clojure.test]
[taoensso.timbre :as timbre :only (info)]))
(deftest test-nothing) ; TODO

5
test/test_timbre/timbre/profiling.clj
View File

@ -1,5 +0,0 @@
(ns test-timbre.timbre.profiling
(:use [clojure.test]
[taoensso.timbre :as timbre :only (info)]))
(deftest test-nothing) ; TODO