Merge branch 'dev'

README.md

@@ -1,7 +1,7 @@
 Current [semantic](http://semver.org/) version:
 
 ```clojure
-[com.taoensso/timbre "1.4.0"]
+[com.taoensso/timbre "1.5.0"]
 ```
 
 # 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.4.0"]
+[com.taoensso/timbre "1.5.0"]
 ```
 
 and `use` the library:

project.clj

@@ -1,4 +1,4 @@
-(defproject com.taoensso/timbre "1.4.0"
+(defproject com.taoensso/timbre "1.5.0"
   :description "Clojure logging & profiling library"
   :url "https://github.com/ptaoussanis/timbre"
   :license {:name "Eclipse Public License"}

src/taoensso/timbre.clj

@@ -140,19 +140,20 @@
    ((fn [apfn]
       (if-not max-message-per-msecs
         apfn
-        (let [;; {:msg last-appended-time-msecs ...}
+        (let [;; {:hash last-appended-time-msecs ...}
               flood-timers (atom {})]
 
-          (fn [{:keys [message] :as apfn-args}]
+          (fn [{:keys [ns message] :as apfn-args}]
             (let [now    (System/currentTimeMillis)
+                  hash   (str ns "/" message)
                   allow? (fn [last-msecs]
                            (if last-msecs
                              (> (- now last-msecs) max-message-per-msecs)
                              true))]
 
-              (when (allow? (@flood-timers message))
+              (when (allow? (@flood-timers hash))
                 (apfn apfn-args)
-                (swap! flood-timers assoc message now))
+                (swap! flood-timers assoc hash now))
 
               ;; Occassionally garbage-collect all expired timers. Note
               ;; that due to snapshotting, garbage-collection can cause
@@ -366,8 +367,11 @@
 (defmacro log-and-rethrow-errors
   [& body] `(try ~@body (catch Exception e# (error e#) (throw e#))))
 
+(defmacro logged-future [& body] `(future (log-errors ~@body)))
+
 (comment (log-errors (/ 0))
-         (log-and-rethrow-errors (/ 0)))
+         (log-and-rethrow-errors (/ 0))
+         (logged-future (/ 0)))
 
 ;;;; Dev/tests
 

src/taoensso/timbre/frequencies.clj

@@ -0,0 +1,76 @@
+(ns taoensso.timbre.frequencies
+  "Frequency logger for Timbre. ALPHA quality."
+  {:author "Peter Taoussanis"}
+  (:require [clojure.string        :as str]
+            [taoensso.timbre       :as timbre]
+            [taoensso.timbre.utils :as utils]))
+
+(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*})))
+
+(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
+  queryable db logging)."
+  [level name & body]
+  (let [name (utils/fq-keyword name)]
+    `(let [{result# :result stats# :stats} (with-fdata ~level ~@body)]
+       (when stats#
+         (timbre/log* ~level
+                      {:frequency-stats stats#}
+                      (str "Frequencies " ~name)
+                      (str "\n" (fdata-table stats#))))
+       result#)))
+
+(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."
+  [name & body]
+  (let [name (utils/fq-keyword name)]
+    `(if-not *fdata*
+       (do ~@body)
+       (let [name#   ~name
+             result# (do ~@body)]
+         (swap! *fdata* #(assoc-in % [name# result#]
+                                  (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."
+  [stats]
+  (let [sorted-fnames (sort (keys stats))
+        sorted-fvals  (fn [form-stats] (reverse (sort-by form-stats
+                                                        (keys form-stats))))]
+    (str/join "\n"
+     (for [fname sorted-fnames]
+       (let [form-stats (stats fname)
+             sorted-fvs (sorted-fvals form-stats)]
+         (str fname " "
+              (str/join " "
+                (mapv (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
+  (with-fdata :info
+    (vec (repeatedly 20 (fn [] (fspy :rand-nth (rand-nth [:a :b :c]))))))
+
+  (log-frequencies
+   :info :my-frequencies
+   (vec (repeatedly 20 (fn [] (fspy :rand-nth (rand-nth [:a :b :c])))))))

src/taoensso/timbre/profiling.clj

@@ -1,34 +1,64 @@
 (ns taoensso.timbre.profiling
-  "Simple all-Clojure profiling adapted from clojure.contrib.profile."
+  "Logging profiler for Timbre, adapted from clojure.contrib.profile."
   {:author "Peter Taoussanis"}
   (:require [taoensso.timbre       :as timbre]
             [taoensso.timbre.utils :as utils]))
 
-(def ^:dynamic *plog* "{::pname [time1 time2 ...] ...}" nil)
+(def ^:dynamic *pdata* "{::pname [time1 time2 ...] ...}" nil)
 
-(defmacro prepare-name
+(declare p pdata-stats pdata-table)
-  "Returns namespaced keyword for given name."
-  [name]
-  `(if (and (keyword? ~name) (namespace ~name))
-     ~name
-     (keyword (str ~*ns*) (clojure.core/name ~name))))
 
-(defmacro p
+(defmacro with-pdata
-  "When in the context of a *plog* binding, records execution time of named
+  [level & body]
-  body. Always returns the body's result."
+  `(if-not (timbre/logging-enabled? ~level)
+     {:result (do ~@body)}
+     (binding [*pdata* (atom {})]
+       {:result (p ::clock-time ~@body) :stats (pdata-stats @*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)."
+  [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#))))
+       result#)))
+
+(defmacro sampling-profile
+  "Like `profile`, but only enables profiling every 1/`proportion` calls.
+  Always returns body's result."
+  [level proportion name & body]
+  `(if-not (> ~proportion (rand))
+     (do ~@body)
+     (profile ~level ~name ~@body)))
+
+(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]
-  (let [name (prepare-name name)]
+  (let [name (utils/fq-keyword name)]
-    `(if *plog*
+    `(if-not *pdata*
+       (do ~@body)
        (let [start-time# (System/nanoTime)
              result#     (do ~@body)
              elapsed#    (- (System/nanoTime) start-time#)]
-         (swap! *plog* #(assoc % ~name (conj (% ~name []) elapsed#)))
+         (swap! *pdata* #(assoc % ~name (conj (% ~name []) elapsed#)))
-         result#)
+         result#))))
-       (do ~@body))))
 
-(defn plog-stats
+(defmacro p [name & body] `(pspy ~name ~@body)) ; Alias
+
+(defn pdata-stats
   "{::pname [time1 time2 ...] ...} => {::pname {:min <min-time> ...} ...}"
-  [plog]
+  [pdata]
   (reduce (fn [m [pname times]] ; TODO reduce-kv for Clojure 1.4+
             (let [count (count times)
                   time  (reduce + times)
@@ -43,16 +73,11 @@
                               :mean  mean
                               :mad   mad
                               :time  time})))
-          {} plog))
+          {} pdata))
 
-(defn fqname
+(defn pdata-table
-  "Like `name` but returns fully-qualified name."
+  "Returns formatted table string for given pdata stats."
-  [keyword]
+  ([stats] (pdata-table stats :time))
-  (str (namespace keyword) "/" (name keyword)))
-
-(defn plog-table
-  "Returns formatted table string for given plog stats."
-  ([stats] (plog-table stats :time))
   ([stats sort-field]
      (let [;; How long entire (profile) body took
            clock-time (-> stats ::clock-time :time)
@@ -80,53 +105,13 @@
          (doseq [pname (->> (keys stats)
                             (sort-by #(- (get-in stats [% sort-field]))))]
            (let [{:keys [count min max mean mad time]} (stats pname)]
-             (printf pattern (fqname pname) count (ft min) (ft max) (ft mad)
+             (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))))))
 
-(defmacro profile*
-  "Executes named body with profiling enabled. Body forms wrapped in (p) will be
-  timed and time stats sent along with `name` to binary `log-fn`. Returns body's
-  result."
-  [log-fn name & body]
-  (let [name (prepare-name name)]
-    `(binding [*plog* (atom {})]
-       (let [result# (do ~@body)]
-         (~log-fn ~name (plog-stats @*plog*))
-         result#))))
-
-(defmacro profile
-  "When logging is enabled, executes named body with profiling enabled. Body
-  forms wrapped in (p) 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. One common use is
-  for db appenders to check for this special key and to log profiling stats to
-  db in a queryable manner."
-  [level name & body]
-  `(if (timbre/logging-enabled? ~level)
-     (profile*
-      (fn [name# stats#]
-        (timbre/log* ~level
-                     {:profile-stats stats#}
-                     (str "Profiling " (fqname name#))
-                     (str "\n" (plog-table stats#))))
-      ~name
-      (p ::clock-time ~@body))
-     (do ~@body)))
-
-(defmacro sampling-profile
-  "Like `profile`, but only enables profiling every 1/`proportion` calls.
-  Always returns body's result."
-  [level proportion name & body]
-  `(if (> ~proportion (rand))
-     (profile ~level ~name ~@body)
-     (do ~@body)))
-
 (comment
   (profile :info :Sleepy-threads
            (dotimes [n 5]
@@ -138,7 +123,7 @@
              (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 *pdata* context)
 
   (defn my-fn
     []

src/taoensso/timbre/utils.clj

@@ -54,4 +54,13 @@
       (/ (Math/round (* x modifier)) modifier))))
 
 (comment (round-to 0 10)
-         (round-to 2 10.123))
+         (round-to 2 10.123))
+
+(defmacro fq-keyword
+  "Returns namespaced keyword for given name."
+  [name]
+  `(if (and (keyword? ~name) (namespace ~name))
+     ~name
+     (keyword (str ~*ns*) (clojure.core/name ~name))))
+
+(comment (map #(fq-keyword %) ["foo" :foo :foo/bar]))