Merge branch 'dev': v0.6.1.

README.md

@@ -1,7 +1,7 @@
-Current version:
+Current [semantic](http://semver.org/) version:
 
 ```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
@@ -37,7 +37,7 @@ lein2 all test
 Depend on Timbre in your `project.clj`:
 
 ```clojure
-[com.taoensso/timbre "0.6.0"]
+[com.taoensso/timbre "0.6.1"]
 ```
 
 and `use` the library:
@@ -207,23 +207,23 @@ The `profile` macro can now be used to log times for any wrapped forms:
 ```clojure
 (profile :info :Arithmetic (dotimes [n 100] (my-fn)))
 => "Done!"
-%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling: my-app/Arithmetic
-              Name  Count       Min        Max      Mean  Total% Total
- my-app/slow-sleep    100       2ms        2ms       2ms      58 232ms
- my-app/fast-sleep    100       1ms        1ms       1ms      30 120ms
-        my-app/div    100      65μs      204μs      90μs       2 9ms
-        my-app/add    100      32μs      116μs      59μs       1 5ms
-        my-app/sub    100      30μs      145μs      47μs       1 4ms
-       my-app/mult    100      33μs      117μs      45μs       1 4ms
-       Unaccounted                                             6 25ms
-             Total                                           100 403ms
+%> 2012-Jul-03 20:46:17 +0700 INFO [my-app] - Profiling my-app/Arithmetic
+              Name  Calls       Min        Max       MAD      Mean  Total% Total
+ my-app/slow-sleep    100       2ms        2ms      31μs       2ms      57 231ms
+ my-app/fast-sleep    100       1ms        1ms      27μs       1ms      29 118ms
+        my-app/add    100      44μs        2ms      46μs     100μs       2 10ms
+        my-app/sub    100      42μs      564μs      26μs      72μs       2 7ms
+        my-app/div    100      54μs      191μs      17μs      71μs       2 7ms
+       my-app/mult    100      31μs      165μs      11μs      44μs       1 4ms
+       Unaccounted                                                       6 26ms
+             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*.
 
-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
 

project.clj

@@ -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!"
   :url "https://github.com/ptaoussanis/timbre"
   :license {:name "Eclipse Public License"}

src/taoensso/timbre.clj

@@ -217,7 +217,7 @@
                  (not-any? (partial ns-match? ns) ns-blacklist))))))
    (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-ns-filter!)

src/taoensso/timbre/profiling.clj

@@ -30,11 +30,17 @@
   [plog]
   (reduce (fn [m [pname 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
                               :min   (apply min times)
                               :max   (apply max times)
-                              :mean  (long (/ total count))
+                              :mean  mean
+                              :mad   mad
                               :total total})))
           {} plog))
 
@@ -44,7 +50,7 @@
   (str (namespace keyword) "/" (name keyword)))
 
 (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 sort-field]
      (let [;; How long entire (profile) body took
@@ -56,7 +62,7 @@
 
            max-name-width (apply max (map (comp count str)
                                           (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)
 
            perc #(Math/round (/ %1 %2 0.01))
@@ -70,19 +76,18 @@
                         :else (str (long nanosecs)  "ns"))))]
 
        (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)
                             (sort-by #(- (get-in stats [% sort-field]))))]
-           (let [{:keys [count min max mean total]} (stats pname)]
-             (printf pattern (fqname pname) count (ft min) (ft max) (ft mean)
-                     (perc total total-time)
-                     (ft total))))
+           (let [{:keys [count min max mean mad total]} (stats pname)]
+             (printf pattern (fqname pname) count (ft min) (ft max) (ft mad)
+                     (ft mean) (perc total total-time) (ft total))))
 
          (let [unacc      (- total-time accounted)
                unacc-perc (perc unacc total-time)]
-           (printf s-pattern "Unaccounted" "" "" "" "" unacc-perc (ft unacc))
-           (printf s-pattern "Total" "" "" "" "" 100 (ft total-time)))))))
+           (printf s-pattern "Unaccounted" "" "" "" "" "" unacc-perc (ft unacc))
+           (printf s-pattern "Total" "" "" "" "" "" 100 (ft total-time)))))))
 
 (defmacro profile*
   "Executes named body with profiling enabled. Body forms wrapped in (p) will be
@@ -111,7 +116,7 @@
       (fn [name# stats#]
         (timbre/log* ~level
                      {:profile-stats stats#}
-                     (str "Profiling: " (fqname name#))
+                     (str "Profiling " (fqname name#))
                      (str "\n" (plog-table stats#))))
       ~name
       (p :meta/total ~@body))
@@ -127,12 +132,14 @@
 
 (comment
   (profile :info :Sleepy-threads
-           (Thread/sleep 100) ; Unaccounted
-           (p :1ms  (Thread/sleep 1))
-           (p :2s   (Thread/sleep 2000))
-           (p :50ms (Thread/sleep 50))
-           (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 *plog* context)
 

test/test_taoensso/timbre.clj

@@ -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