Merge branch 'dev'

README.md

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

project.clj

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

src/taoensso/timbre/frequencies.clj

@@ -7,22 +7,22 @@
 
 (def ^:dynamic *fdata* "{::fname {form-value frequency}}" nil)
 
-(declare fdata-table)
-
 (defmacro with-fdata
   [level & body]
   `(if-not (timbre/logging-enabled? ~level)
      {:result (do ~@body)}
      (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

src/taoensso/timbre/profiling.clj

@@ -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,22 +15,24 @@
      (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)]
        (when stats#
          (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)
-
-           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"))))]
-
-       (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))))
-
-         (printf s-pattern "[Clock] Time" "" "" "" "" "" 100 (ft clock-time))
-         (printf s-pattern "Accounted Time" "" "" "" "" ""
-                 (perc accounted clock-time) (ft accounted))))))
+(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)
+
+        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")
+
+      (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)))))
 
 (comment
   (profile :info :Sleepy-threads