diff --git a/README.md b/README.md index 9d75f84..122b268 100644 --- a/README.md +++ b/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: diff --git a/project.clj b/project.clj index 75afdb1..26088e7 100644 --- a/project.clj +++ b/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"} diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index 2ac563d..0d708ef 100644 --- a/src/taoensso/timbre.clj +++ b/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 diff --git a/src/taoensso/timbre/frequencies.clj b/src/taoensso/timbre/frequencies.clj new file mode 100644 index 0000000..67154ae --- /dev/null +++ b/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]))))))) \ No newline at end of file diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index 82ad42f..20a10b0 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/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 - "Returns namespaced keyword for given name." - [name] - `(if (and (keyword? ~name) (namespace ~name)) - ~name - (keyword (str ~*ns*) (clojure.core/name ~name)))) +(declare p pdata-stats pdata-table) -(defmacro p - "When in the context of a *plog* binding, records execution time of named - body. Always returns the body's result." +(defmacro with-pdata + [level & body] + `(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)] - `(if *plog* + (let [name (utils/fq-keyword name)] + `(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#))) - result#) - (do ~@body)))) + (swap! *pdata* #(assoc % ~name (conj (% ~name []) elapsed#))) + result#)))) -(defn plog-stats +(defmacro p [name & body] `(pspy ~name ~@body)) ; Alias + +(defn pdata-stats "{::pname [time1 time2 ...] ...} => {::pname {:min ...} ...}" - [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 - "Like `name` but returns fully-qualified name." - [keyword] - (str (namespace keyword) "/" (name keyword))) - -(defn plog-table - "Returns formatted table string for given plog stats." - ([stats] (plog-table stats :time)) +(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) @@ -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 [] diff --git a/src/taoensso/timbre/utils.clj b/src/taoensso/timbre/utils.clj index b2632b2..33af150 100644 --- a/src/taoensso/timbre/utils.clj +++ b/src/taoensso/timbre/utils.clj @@ -54,4 +54,13 @@ (/ (Math/round (* x modifier)) modifier)))) (comment (round-to 0 10) - (round-to 2 10.123)) \ No newline at end of file + (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])) \ No newline at end of file