Permalink
Browse files

Merge branch 'dev'

  • Loading branch information...
2 parents de5ab76 + ba172df commit b0738b73b46a650c40c2b911b572f0d926d252e9 @ptaoussanis committed Feb 7, 2013
Showing with 152 additions and 78 deletions.
  1. +2 −2 README.md
  2. +1 −1 project.clj
  3. +9 −5 src/taoensso/timbre.clj
  4. +76 −0 src/taoensso/timbre/frequencies.clj
  5. +54 −69 src/taoensso/timbre/profiling.clj
  6. +10 −1 src/taoensso/timbre/utils.clj
View
@@ -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:
View
@@ -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"}
@@ -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
@@ -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])))))))
@@ -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#))))
+
+(defmacro p [name & body] `(pspy ~name ~@body)) ; Alias
-(defn plog-stats
+(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
- "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
[]
@@ -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]))

0 comments on commit b0738b7

Please sign in to comment.