From a1bec9d6c320741b1eacc2c497edac2c1a5695e6 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:24:29 +0700 Subject: [PATCH 1/9] Allow Travis to test dev branches. --- .travis.yml | 3 --- 1 file changed, 3 deletions(-) diff --git a/.travis.yml b/.travis.yml index 0a8cf78..e1ae6be 100644 --- a/.travis.yml +++ b/.travis.yml @@ -1,9 +1,6 @@ language: clojure lein: lein2 script: lein2 all test -branches: - only: - - master jdk: - openjdk7 - openjdk6 From cfc2a60c8e7e4f12a4e16b2bfc946243dd60a840 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:27:20 +0700 Subject: [PATCH 2/9] BREAKING: New ns structure. --- src/{timbre/core.clj => taoensso/timbre.clj} | 2 +- test/{timbre/test/core.clj => test_timbre/timbre.clj} | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) rename src/{timbre/core.clj => taoensso/timbre.clj} (99%) rename test/{timbre/test/core.clj => test_timbre/timbre.clj} (53%) diff --git a/src/timbre/core.clj b/src/taoensso/timbre.clj similarity index 99% rename from src/timbre/core.clj rename to src/taoensso/timbre.clj index f25980a..a8c33b2 100644 --- a/src/timbre/core.clj +++ b/src/taoensso/timbre.clj @@ -1,4 +1,4 @@ -(ns timbre.core +(ns taoensso.timbre "Simple, flexible, all-Clojure logging. No XML!" {:author "Peter Taoussanis"} (:require [clojure.string :as str] diff --git a/test/timbre/test/core.clj b/test/test_timbre/timbre.clj similarity index 53% rename from test/timbre/test/core.clj rename to test/test_timbre/timbre.clj index b6f745a..d32a3b5 100644 --- a/test/timbre/test/core.clj +++ b/test/test_timbre/timbre.clj @@ -1,6 +1,6 @@ -(ns timbre.test.core +(ns test-timbre.timbre (:use [clojure.test] - [timbre.core :as timbre :only (info)])) + [taoensso.timbre :as timbre :only (info)])) ;; TODO Tests (help would be welcome!!) From 0177e7236b345533504e6d08b37d1aa7c8cc32b4 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:29:11 +0700 Subject: [PATCH 3/9] Added ns filtering, `logging-enabled`. Misc housekeeping. --- src/taoensso/timbre.clj | 176 +++++++++++++++++++++++++--------------- 1 file changed, 112 insertions(+), 64 deletions(-) diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index a8c33b2..a9b0a10 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -5,7 +5,7 @@ [clj-stacktrace.repl :as stacktrace] [postal.core :as postal]) (:import [java.util Date Locale] - java.text.SimpleDateFormat)) + [java.text.SimpleDateFormat])) ;;;; Default configuration and appenders @@ -16,7 +16,7 @@ " [" ns "] - " message)) (defn str-println - "Like 'println' but prints all objects to output stream as a single + "Like `println` but prints all objects to output stream as a single atomic string. This is faster and avoids interleaving race conditions." [& xs] (print (str (str/join \space xs) \newline))) @@ -29,11 +29,17 @@ :doc, :min-level, :enabled?, :async?, :max-message-per-msecs, :fn? An appender's fn takes a single map argument with keys: - :ap-config, :level, :error?, :instant, :timestamp, :ns, :message, :more + :ap-config, :level, :error?, :instant, :timestamp, :ns, :message, :more, + :profiling-stats (when applicable) See source code for examples." (atom {:current-level :debug + ;;; Allow log filtering by namespace patterns (e.g. ["my-app.*"]). + ;;; Useful for turning off logging in noisy libraries, etc. + :ns-whitelist [] + :ns-blacklist [] + :appenders {:standard-out {:doc "Prints everything to *out*." @@ -63,6 +69,7 @@ :body (if (seq more) (str/join " " more) "")))))}} + ;; Will be given to all appenders via :ap-config key :shared-appender-config {:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" ; SimpleDateFormat pattern :locale nil ; A Locale object, or nil @@ -71,11 +78,14 @@ ;; {:from "me@draines.com" :to "foo@example.com"} :postal nil}})) +(defn set-config! [[k & ks] val] (swap! config assoc-in (cons k ks) val)) +(defn set-level! [level] (set-config! [:current-level] level)) + ;;;; Define and sort logging levels (def ^:private ordered-levels [:trace :debug :info :warn :error :fatal :report]) (def ^:private scored-levels (zipmap ordered-levels (range))) -(defn check-level +(defn assert-valid-level [x] (when-not (some #{x} ordered-levels) (throw (Exception. (str "Invalid logging level: " x))))) @@ -85,14 +95,6 @@ (defn sufficient-level? [level] (>= (compare-levels level (:current-level @config)) 0)) -;;;; Config helpers - -(defn set-config! [[k & ks] val] (swap! config assoc-in (cons k ks) val)) -(defn set-level! - [level] - (check-level level) - (set-config! [:current-level] level)) - ;;;; Appender-fn decoration (defn- make-timestamp-fn @@ -107,8 +109,8 @@ (comment ((make-timestamp-fn "yyyy-MMM-dd" nil) (Date.))) (defn- wrap-appender-fn - "Wraps compile-time appender fn with additional capabilities controlled by - compile-time config." + "Wraps compile-time appender fn with additional runtime capabilities + controlled by compile-time config." [{apfn :fn :keys [async? max-message-per-msecs] :as appender}] (-> ;; Wrap to add compile-time stuff to runtime appender arguments @@ -132,7 +134,7 @@ ((fn [apfn] (if-not max-message-per-msecs apfn - (let [ ;; {:msg last-appended-time-msecs ...} + (let [;; {:msg last-appended-time-msecs ...} flood-timers (atom {})] (fn [{:keys [message] :as apfn-args}] @@ -157,10 +159,13 @@ (when (seq expired-timers) (apply swap! flood-timers dissoc expired-timers)))))))))))) -;;;; Appender-fn caching +;;;; Caching -(def juxt-cache - "Per-level, combined relevant appender-fns: +;;; Appender-fns + +(def appenders-juxt-cache + "Per-level, combined relevant appender-fns to allow for fast runtime + appender-fn dispatch: {:level (juxt wrapped-appender-fn wrapped-appender-fn ...) or nil ...}" (atom {})) @@ -176,63 +181,97 @@ (comment (relevant-appenders :debug) (relevant-appenders :trace)) -(defn- cache-appenders! - "Prime 'juxt-cache' for fast runtime appender-fn dispatch." +(defn- cache-appenders-juxt! [] - (->> (zipmap - ordered-levels - (->> ordered-levels - (map (fn [l] (let [rel-aps (relevant-appenders l)] - ;; Return nil if no relevant appenders - (when-let [ap-ids (keys rel-aps)] - (->> ap-ids - (map #(wrap-appender-fn (rel-aps %))) - (apply juxt)))))))) - (reset! juxt-cache))) + (->> + (zipmap + ordered-levels + (->> ordered-levels + (map (fn [l] (let [rel-aps (relevant-appenders l)] + ;; Return nil if no relevant appenders + (when-let [ap-ids (keys rel-aps)] + (->> ap-ids + (map #(wrap-appender-fn (rel-aps %))) + (apply juxt)))))))) + (reset! appenders-juxt-cache))) -(cache-appenders!) ; Actually cache default appenders now +;;; Namespace filter + +(def ns-filter-cache "@ns-filter-cache => (fn relevant-ns? [ns] ...)" + (atom (constantly true))) + +(defn- ns-match? + [ns match] + (-> (str "^" (-> (str match) (.replace "." "\\.") (.replace "*" "(.*)")) "$") + re-pattern (re-find (str ns)) boolean)) + +(defn- cache-ns-filter! + [] + (->> + (let [{:keys [ns-whitelist ns-blacklist]} @config] + (memoize + (fn relevant-ns? [ns] + (and (or (empty? ns-whitelist) + (some (partial ns-match? ns) ns-whitelist)) + (or (empty? ns-blacklist) + (not-any? (partial ns-match? ns) ns-blacklist)))))) + (reset! ns-filter-cache))) + +;;; Prime initial caches and recache on config change + +(cache-appenders-juxt!) +(cache-ns-filter!) -;; Automatically re-cache any time appenders change (add-watch - config "appender-watch" + config "config-cache-watch" (fn [key ref old-state new-state] (when (not= (dissoc old-state :current-level) (dissoc new-state :current-level)) - (cache-appenders!)))) + (cache-appenders-juxt!) + (cache-ns-filter!)))) ;;;; Define logging macros +(defmacro logging-enabled? + "Returns true when current logging level is sufficient and current namespace + is unfiltered." + [level] + (assert-valid-level level) + `(and (sufficient-level? ~level) (@ns-filter-cache ~*ns*))) + +(defmacro log* + "Prepares given arguments for, and then dispatches to all relevant + appender-fns." + [level base-args & args] + (assert-valid-level level) + `(when-let [juxt-fn# (@appenders-juxt-cache ~level)] ; Any relevant appenders? + (let [[x1# & xs#] (list ~@args) + + has-throwable?# (instance? Throwable x1#) + appender-args# + (conj + ~base-args ; Allow flexibility to inject exta args + {:level ~level + :error? (>= (compare-levels ~level :error) 0) + :instant (Date.) + :ns (str ~*ns*) + :message (if has-throwable?# (or (first xs#) x1#) x1#) + :more (if has-throwable?# + (conj (vec (rest xs#)) + (str "\n" (stacktrace/pst-str x1#))) + (vec xs#))})] + + (juxt-fn# appender-args#) + nil))) + (defmacro log - "Dispatches given arguments to relevant appender-fns iff logging level is - sufficient." + "When logging is enabled, actually logs given arguments with relevant + appender-fns. Generic form of standard level-loggers (trace, info, etc.)." {:arglists '([level message & more] [level throwable message & more])} [level & args] - (check-level level) - `(let [level# ~level] - (when (sufficient-level? level#) - (when-let [juxt-fn# (@juxt-cache level#)] ; Any relevant appenders? - (let [[x1# & xs#] (list ~@args) - - has-throwable?# (instance? Throwable x1#) - appender-args# - {:level level# - :error? (>= (compare-levels level# :error) 0) - :instant (Date.) - :ns (str ~*ns*) - :message (if has-throwable?# (or (first xs#) x1#) x1#) - :more (if has-throwable?# - (conj (vec (rest xs#)) - (str "\n" (stacktrace/pst-str x1#))) - (vec xs#))}] - - (juxt-fn# appender-args#) - nil))))) - -(comment (log :fatal "arg1") - (log :debug "arg1" "arg2") - (log :debug (Exception.) "arg1" "arg2") - (log :debug (Exception.)) - (log :trace "arg1")) + (assert-valid-level level) + `(when (logging-enabled? ~level) + (log* ~level {} ~@args))) (defmacro spy "Evaluates expression and logs its form and result. Always returns the result. @@ -240,7 +279,7 @@ ([expr] `(spy :debug ~expr)) ([level expr] `(try - (let [r# ~expr] (log ~level '~expr ~expr) r#) + (let [result# ~expr] (log ~level '~expr ~expr) result#) (catch Exception e# (log ~level '~expr (str "\n" (stacktrace/pst-str e#))) (throw e#))))) @@ -262,9 +301,18 @@ ;;;; Dev/tests (comment + (log :fatal "arg1") + (log :debug "arg1" "arg2") + (log :debug (Exception.) "arg1" "arg2") + (log :debug (Exception.)) + (log :trace "arg1") + + (set-config! [:ns-blacklist] []) + (set-config! [:ns-blacklist] ["taoensso.timbre*"]) + (info "foo" "bar") (trace (Thread/sleep 5000)) - (time (dotimes [n 10000] (trace "This won't log"))) ; Minimum overhead +/- 4.5ms + (time (dotimes [n 10000] (trace "This won't log"))) ; Overhead 5ms/10ms (time (dotimes [n 5] (info "foo" "bar"))) (spy (* 6 5 4 3 2 1)) (info (Exception. "noes!") "bar") From d9a68f1e585abfc413f4e3a049ec4e79bb5e10b9 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:30:50 +0700 Subject: [PATCH 4/9] README tweaks. --- README.md | 43 +++++++++++++++++++++++++++++++++++++++---- 1 file changed, 39 insertions(+), 4 deletions(-) diff --git a/README.md b/README.md index 570f18f..f7c8769 100644 --- a/README.md +++ b/README.md @@ -23,9 +23,13 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin * Tunable **flood control**. * **Asynchronous** logging support. -## Status [![Build Status](https://secure.travis-ci.org/ptaoussanis/timbre.png)](http://travis-ci.org/ptaoussanis/timbre) +## Status [![Build Status](https://secure.travis-ci.org/ptaoussanis/timbre.png?branch=master)](http://travis-ci.org/ptaoussanis/timbre) -Timbre was built in a day after I finally lost my patience trying to configure Log4j. I tried to keep the design simple and sensible but I didn't spend much time thinking about it so there may still be room for improvement. In particular **the configuration and appender formats are still subject to change**. +Tower is still currently *experimental*. It **has not yet been thoroughly tested in production** and its API is subject to change. To run tests against all supported Clojure versions, use: + +```bash +lein2 all test +``` ## Getting Started @@ -37,7 +41,7 @@ Depend on Timbre in your `project.clj`: [com.taoensso/timbre "0.5.2"] ``` -and `require` the library: +and `use` the library: ```clojure (ns my-app @@ -79,6 +83,32 @@ java.lang.Exception: Oh noes ### Configuration +Configuring Timbre couldn't be simpler. Let's check out (some of) the defaults: + +```clojure +@timbre/config +=> +{:current-level :debug + + :ns-whitelist [] + :ns-blacklist [] + + :appenders + {:standard-out + {:doc "Prints everything to *out*." + :min-level nil :enabled? false :async? false + :max-message-per-msecs nil + :fn (fn [{:keys [more] :as args}] + (apply timbre/str-println (timbre/prefixed-message args) more))} + ;; ... + } + + :shared-appender-config + {:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" + :locale nil + :postal nil}} +``` + Easily adjust the current logging level: ```clojure @@ -94,6 +124,11 @@ And the default timestamp formatting for log messages: (java.util.Locale/GERMAN)) ``` +Filter logging output by namespaces: +```clojure +(timbre/set-config! [:ns-whitelist] ["some.library.core" "my-app.*"]) +``` + Enable the standard [Postal](https://github.com/drewr/postal)-based email appender: ```clojure @@ -118,7 +153,7 @@ And make sure emails are sent asynchronously: ### Custom Appenders -Writing a custom appender is easy: +Writing a custom appender is dead-easy: ```clojure (timbre/set-config! From aaca1aac5d18b9de1a103ee77ed4f0fea9b242f0 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:32:08 +0700 Subject: [PATCH 5/9] Added timbre.profiling as merge from abandoned Touchstone library. --- src/taoensso/timbre/profiling.clj | 128 ++++++++++++++++++++++++++++++ 1 file changed, 128 insertions(+) create mode 100644 src/taoensso/timbre/profiling.clj diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj new file mode 100644 index 0000000..f9d767a --- /dev/null +++ b/src/taoensso/timbre/profiling.clj @@ -0,0 +1,128 @@ +(ns taoensso.timbre.profiling + "Simple all-Clojure profiling adapted from clojure.contrib.profile." + {:author "Peter Taoussanis"} + (:require [taoensso.timbre :as timbre])) + +(def ^:dynamic *plog* "{::pname [time1 time2 ...] ...}" nil) + +(defmacro p + "When in the context of a *plog* binding, records execution time of named + body. Always returns the body's result." + [name & body] + (let [name (keyword (str *ns*) (clojure.core/name name))] + `(if *plog* + (let [start-time# (System/nanoTime) + result# (do ~@body) + elapsed# (- (System/nanoTime) start-time#)] + (swap! *plog* #(assoc % ~name (conj (% ~name []) elapsed#))) + result#) + (do ~@body)))) + +(defn plog-stats + "{::pname [time1 time2 ...] ...} => {::pname {:min ...} ...}" + [plog] + (reduce (fn [m [pname times]] + (let [count (count times) + total (reduce + times)] + (assoc m pname {:count count + :min (apply min times) + :max (apply max times) + :mean (int (/ total count)) + :total total}))) + {} plog)) + +(defn fqname + "Like `name` but returns fully-qualified name." + [keyword] + (str (namespace keyword) "/" (name keyword))) + +(defn plog-table + "Returns formatted plog stats table for given plog stats." + ([stats] (plog-table stats :total)) + ([stats sort-field] + (let [grand-total-time (reduce + (map :total (vals stats))) + max-name-width (apply max (map (comp count str) + (conj (keys stats) "Event"))) + pattern (str " %" max-name-width "s %6d %9s %10s %9s %7d %1s%n") + s-pattern (.replace pattern \d \s) + + ft (fn [nanosecs] + (let [pow #(Math/pow 10 %) + ok-pow? #(>= nanosecs (pow %)) + to-pow #(long (/ nanosecs (pow %)))] + (cond (ok-pow? 9) (str (to-pow 9) "s") + (ok-pow? 6) (str (to-pow 6) "ms") + (ok-pow? 3) (str (to-pow 3) "μs") + :else (str (long nanosecs) "ns"))))] + + (with-out-str + (printf s-pattern "Event" "Count" "Min" "Max" "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) + (Math/round (/ total grand-total-time 0.01)) + (ft total)))) + + (printf s-pattern "" "" "" "" "" "" (ft grand-total-time)))))) + +(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 (keyword (str *ns*) (clojure.core/name name))] + `(binding [*plog* (atom {})] + (let [result# (do ~@body)] + (~log-fn ~name (plog-stats @*plog*)))))) + +(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] + (timbre/assert-valid-level level) + `(if (timbre/logging-enabled? ~level) + (profile* + (fn [name# stats#] + (timbre/log* ~level + {:profile-stats stats#} + (str "Profiling table: " (fqname name#)) + (plog-table stats#))) + ~name + ~@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 + (p :1ms (Thread/sleep 1)) + (p :2s (Thread/sleep 2000)) + (p :50ms (Thread/sleep 50)) + (p :10ms (Thread/sleep 10)) + "Result") + + (p :hello "Hello, this is a result") ; Falls through (no *plog* context) + + (let [nums (range 1000)] + (profile :info :Arithmetic + (dotimes [n 1000] + (p :add (reduce + nums)) + (p :subtract (reduce - nums)) + (p :multiply (reduce * nums)) + (p :divide (reduce / nums))))) + + (sampling-profile :info 0.2 :Sampling-test (p :string "Hello!"))) \ No newline at end of file From aa531901ea1b4d99964422d6f8dca4fb0fdaf005 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:32:44 +0700 Subject: [PATCH 6/9] Cleaned up test files. --- test/test_timbre/timbre.clj | 4 +--- test/test_timbre/timbre/profiling.clj | 5 +++++ 2 files changed, 6 insertions(+), 3 deletions(-) create mode 100644 test/test_timbre/timbre/profiling.clj diff --git a/test/test_timbre/timbre.clj b/test/test_timbre/timbre.clj index d32a3b5..eb4662e 100644 --- a/test/test_timbre/timbre.clj +++ b/test/test_timbre/timbre.clj @@ -2,6 +2,4 @@ (:use [clojure.test] [taoensso.timbre :as timbre :only (info)])) -;; TODO Tests (help would be welcome!!) - -(deftest test-nothing) +(deftest test-nothing) ; TODO diff --git a/test/test_timbre/timbre/profiling.clj b/test/test_timbre/timbre/profiling.clj new file mode 100644 index 0000000..4c4a3de --- /dev/null +++ b/test/test_timbre/timbre/profiling.clj @@ -0,0 +1,5 @@ +(ns test-timbre.timbre.profiling + (:use [clojure.test] + [taoensso.timbre :as timbre :only (info)])) + +(deftest test-nothing) ; TODO \ No newline at end of file From bf7c9ff0f6fc2f9cb1b3a12c1c4a8f69199245ab Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 16:54:15 +0700 Subject: [PATCH 7/9] Cleaned up profiling table display. --- src/taoensso/timbre/profiling.clj | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index f9d767a..dbbb85f 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -43,7 +43,7 @@ (let [grand-total-time (reduce + (map :total (vals stats))) max-name-width (apply max (map (comp count str) (conj (keys stats) "Event"))) - pattern (str " %" max-name-width "s %6d %9s %10s %9s %7d %1s%n") + pattern (str "%" max-name-width "s %6d %9s %10s %9s %7d %1s%n") s-pattern (.replace pattern \d \s) ft (fn [nanosecs] @@ -93,8 +93,8 @@ (fn [name# stats#] (timbre/log* ~level {:profile-stats stats#} - (str "Profiling table: " (fqname name#)) - (plog-table stats#))) + (str "Profiling: " (fqname name#)) + (str "\n" (plog-table stats#)))) ~name ~@body) (do ~@body))) From 0cb368a0d9b1a598038f771955c7451ffaf665dd Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 18:48:00 +0700 Subject: [PATCH 8/9] Updated README. Fixed profiler typos. Some other housekeeping. --- README.md | 101 ++++++++++++++++++++++-------- src/taoensso/timbre.clj | 2 +- src/taoensso/timbre/profiling.clj | 25 +++++--- 3 files changed, 92 insertions(+), 36 deletions(-) diff --git a/README.md b/README.md index f7c8769..f67b587 100644 --- a/README.md +++ b/README.md @@ -1,9 +1,7 @@ -# NOTICE - -The Timbre Clojars group was recently changed. Please update your `project.clj` to use: +Current version: ```clojure -[com.taoensso/timbre "{VERSION}"] +[com.taoensso/timbre "0.5.2"] ``` # Timbre, a (sane) logging library for Clojure @@ -16,12 +14,13 @@ Timbre is an attempt to make **simple logging simple** and more **complex loggin ## What's In The Box? * Small, uncomplicated **all-Clojure** library. - * **Super-simple map-based config**: no arcane XML or properties files. + * **Super-simple map-based config**: no arcane XML or properties files! * Decent performance (**low overhead**). * Flexible **fn-centric appender model**. * Sensible built-in appenders including simple **email appender**. - * Tunable **flood control**. - * **Asynchronous** logging support. + * Tunable **flood control** and **asynchronous** logging support. + * Robust **namespace filtering**. + * Dead-simple, logging-level-aware **logging profiler**. ## Status [![Build Status](https://secure.travis-ci.org/ptaoussanis/timbre.png?branch=master)](http://travis-ci.org/ptaoussanis/timbre) @@ -45,7 +44,7 @@ and `use` the library: ```clojure (ns my-app - (:use [timbre.core :as timbre :only (trace debug info warn error fatal spy)]) + (:use [taoensso.timbre :as timbre :only (trace debug info warn error fatal spy)])) ``` ### Start Logging @@ -54,7 +53,12 @@ By default, Timbre gives you basic print output to `*out*`/`*err*` at a `debug` ```clojure (info "This will print") -=> 2012-May-28 17:26:11:444 +0700 INFO [timbre.tests] - This will print +=> nil +%> 2012-May-28 17:26:11:444 +0700 INFO [my-app] - This will print + +(spy :info (* 5 4 3 2 1)) +=> 120 +%> 2012-May-28 17:26:14:138 +0700 INFO [my-app] - (* 5 4 3 2 1) 120 (trace "This won't print due to insufficient logging level") => nil @@ -64,21 +68,21 @@ There's little overhead for checking logging levels: ```clojure (time (trace (Thread/sleep 5000))) -=> "Elapsed time: 0.054 msecs" +%> "Elapsed time: 0.054 msecs" (time (when true)) -=> "Elapsed time: 0.051 msecs" +%> "Elapsed time: 0.051 msecs" ``` First-argument exceptions generate a stack trace: ```clojure (info (Exception. "Oh noes") "arg1" "arg2") -=> 2012-May-28 17:35:16:132 +0700 INFO [timbre.tests] - arg1 arg2 +%> 2012-May-28 17:35:16:132 +0700 INFO [my-app] - arg1 arg2 java.lang.Exception: Oh noes - NO_SOURCE_FILE:1 timbre.tests/eval6409 + NO_SOURCE_FILE:1 my-app/eval6409 Compiler.java:6511 clojure.lang.Compiler.eval - [...] + <...> ``` ### Configuration @@ -94,14 +98,8 @@ Configuring Timbre couldn't be simpler. Let's check out (some of) the defaults: :ns-blacklist [] :appenders - {:standard-out - {:doc "Prints everything to *out*." - :min-level nil :enabled? false :async? false - :max-message-per-msecs nil - :fn (fn [{:keys [more] :as args}] - (apply timbre/str-println (timbre/prefixed-message args) more))} - ;; ... - } + {:standard-out { <...> } + :postal { <...> }} :shared-appender-config {:timestamp-pattern "yyyy-MMM-dd HH:mm:ss ZZ" @@ -165,13 +163,66 @@ Writing a custom appender is dead-easy: :max-message-per-msecs nil ; No rate limiting :fn (fn [{:keys [ap-config level error? instant timestamp ns message more] :as args}] - (when-not (:production-mode? ap-config) + (when-not (:my-production-mode? ap-config) (apply println timestamp "Hello world!" message more))) ``` And because appender fns are just regular Clojure fns, you have *unlimited power*: write to your database, send a message over the network, check some other state (e.g. environment config) before making a choice, etc. -See `(doc timbre/config)` for more information on appenders. +See the `timbre/config` docstring for more information on appenders. + +## Profiling + +The usual recommendation for Clojure profiling is: use a good **JVM profiler** like [YourKit](http://www.yourkit.com/), [JProfiler](http://www.ej-technologies.com/products/jprofiler/overview.html), or [VisualVM](http://docs.oracle.com/javase/6/docs/technotes/guides/visualvm/index.html). + +And these certaily do the job. But as with many Java tools, they can be a little hairy and often heavy-handed - especially when applied to Clojure. Timbre includes an alternative. + +Let's add it to our app's `ns` declaration: + +```clojure +(ns my-app + (:use [taoensso.timbre :as timbre :only (trace debug info warn error fatal spy)] + [taoensso.timbre.profiling :as profiling :only (p profile)])) +``` + +Wrap forms that you'd like to profile with the `p` macro and give them a name: + +```clojure +(defn my-fn + [] + (let [nums (vec (range 1000))] + (+ (p :fast-thread (Thread/sleep 1) 10) + (p :slow-thread (Thread/sleep 2) 32) + (p :add (reduce + nums)) + (p :sub (reduce - nums)) + (p :mult (reduce * nums)) + (p :div (reduce / nums))))) + +(my-fn) +=> 42 +``` + +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 19:39:12 +0700 INFO [my-app] - Profiling: my-app/Arithmetic + Name Count Min Max Mean Total% Total + my-app/slow-thread 100 2ms 2ms 2ms 62 232ms + my-app/fast-thread 100 1ms 1ms 1ms 32 119ms + my-app/div 100 64μs 146μs 79μs 2 7ms + my-app/add 100 24μs 107μs 54μs 1 5ms + my-app/mult 100 33μs 92μs 42μs 1 4ms + my-app/sub 100 30μs 124μs 42μs 1 4ms + 373ms +``` + +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). + +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 logging code*. + +A **sampling profiler** is also available: `taoensso.timbre.profiling/sampling-profile`. ## Timbre Supports the ClojureWerkz Project Goals @@ -187,4 +238,4 @@ I'm also on Twitter: [@ptaoussanis](https://twitter.com/#!/ptaoussanis). Copyright © 2012 Peter Taoussanis -Distributed under the [Eclipse Public License](http://www.eclipse.org/legal/epl-v10.html), the same as Clojure. +Distributed under the [Eclipse Public License](http://www.eclipse.org/legal/epl-v10.html), the same as Clojure. \ No newline at end of file diff --git a/src/taoensso/timbre.clj b/src/taoensso/timbre.clj index a9b0a10..c396353 100644 --- a/src/taoensso/timbre.clj +++ b/src/taoensso/timbre.clj @@ -5,7 +5,7 @@ [clj-stacktrace.repl :as stacktrace] [postal.core :as postal]) (:import [java.util Date Locale] - [java.text.SimpleDateFormat])) + [java.text SimpleDateFormat])) ;;;; Default configuration and appenders diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index dbbb85f..b7309fd 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -42,7 +42,7 @@ ([stats sort-field] (let [grand-total-time (reduce + (map :total (vals stats))) max-name-width (apply max (map (comp count str) - (conj (keys stats) "Event"))) + (conj (keys stats) "Name"))) pattern (str "%" max-name-width "s %6d %9s %10s %9s %7d %1s%n") s-pattern (.replace pattern \d \s) @@ -56,7 +56,7 @@ :else (str (long nanosecs) "ns"))))] (with-out-str - (printf s-pattern "Event" "Count" "Min" "Max" "Mean" "Total%" "Total") + (printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total") (doseq [pname (->> (keys stats) (sort-by #(- (get-in stats [% sort-field]))))] @@ -75,7 +75,8 @@ (let [name (keyword (str *ns*) (clojure.core/name name))] `(binding [*plog* (atom {})] (let [result# (do ~@body)] - (~log-fn ~name (plog-stats @*plog*)))))) + (~log-fn ~name (plog-stats @*plog*)) + result#)))) (defmacro profile "When logging is enabled, executes named body with profiling enabled. Body @@ -117,12 +118,16 @@ (p :hello "Hello, this is a result") ; Falls through (no *plog* context) - (let [nums (range 1000)] - (profile :info :Arithmetic - (dotimes [n 1000] - (p :add (reduce + nums)) - (p :subtract (reduce - nums)) - (p :multiply (reduce * nums)) - (p :divide (reduce / nums))))) + (defn my-fn + [] + (let [nums (vec (range 1000))] + (+ (p :fast-thread (Thread/sleep 1) 10) + (p :slow-thread (Thread/sleep 2) 32) + (p :add (reduce + nums)) + (p :sub (reduce - nums)) + (p :mult (reduce * nums)) + (p :div (reduce / nums))))) + + (profile :info :Arithmetic (dotimes [n 100] (my-fn))) (sampling-profile :info 0.2 :Sampling-test (p :string "Hello!"))) \ No newline at end of file From 123f3c51d9f556de916ea57875767199b9b38328 Mon Sep 17 00:00:00 2001 From: Peter Taoussanis Date: Tue, 3 Jul 2012 20:50:06 +0700 Subject: [PATCH 9/9] Added unaccounted-for timer. Fixed bug with :mean overflow. --- README.md | 25 +++++++++--------- src/taoensso/timbre/profiling.clj | 42 ++++++++++++++++++++++--------- 2 files changed, 43 insertions(+), 24 deletions(-) diff --git a/README.md b/README.md index f67b587..2157f9a 100644 --- a/README.md +++ b/README.md @@ -191,8 +191,8 @@ Wrap forms that you'd like to profile with the `p` macro and give them a name: (defn my-fn [] (let [nums (vec (range 1000))] - (+ (p :fast-thread (Thread/sleep 1) 10) - (p :slow-thread (Thread/sleep 2) 32) + (+ (p :fast-sleep (Thread/sleep 1) 10) + (p :slow-sleep (Thread/sleep 2) 32) (p :add (reduce + nums)) (p :sub (reduce - nums)) (p :mult (reduce * nums)) @@ -207,20 +207,21 @@ 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 19:39:12 +0700 INFO [my-app] - Profiling: my-app/Arithmetic - Name Count Min Max Mean Total% Total - my-app/slow-thread 100 2ms 2ms 2ms 62 232ms - my-app/fast-thread 100 1ms 1ms 1ms 32 119ms - my-app/div 100 64μs 146μs 79μs 2 7ms - my-app/add 100 24μs 107μs 54μs 1 5ms - my-app/mult 100 33μs 92μs 42μs 1 4ms - my-app/sub 100 30μs 124μs 42μs 1 4ms - 373ms +%> 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 ``` 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). -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 logging code*. +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`. diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj index b7309fd..8c9ef5c 100644 --- a/src/taoensso/timbre/profiling.clj +++ b/src/taoensso/timbre/profiling.clj @@ -5,11 +5,18 @@ (def ^:dynamic *plog* "{::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)))) + (defmacro p "When in the context of a *plog* binding, records execution time of named body. Always returns the body's result." [name & body] - (let [name (keyword (str *ns*) (clojure.core/name name))] + (let [name (prepare-name name)] `(if *plog* (let [start-time# (System/nanoTime) result# (do ~@body) @@ -27,7 +34,7 @@ (assoc m pname {:count count :min (apply min times) :max (apply max times) - :mean (int (/ total count)) + :mean (long (/ total count)) :total total}))) {} plog)) @@ -40,12 +47,19 @@ "Returns formatted plog stats table for given plog stats." ([stats] (plog-table stats :total)) ([stats sort-field] - (let [grand-total-time (reduce + (map :total (vals stats))) - max-name-width (apply max (map (comp count str) - (conj (keys stats) "Name"))) + (let [;; How long entire (profile) body took + total-time (-> stats :meta/total :total) + stats (dissoc stats :meta/total) + + ;; Sum of (p) times, <= total-time + accounted (reduce + (map :total (vals stats))) + + 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") 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 %)) @@ -53,7 +67,7 @@ (cond (ok-pow? 9) (str (to-pow 9) "s") (ok-pow? 6) (str (to-pow 6) "ms") (ok-pow? 3) (str (to-pow 3) "μs") - :else (str (long nanosecs) "ns"))))] + :else (str (long nanosecs) "ns"))))] (with-out-str (printf s-pattern "Name" "Count" "Min" "Max" "Mean" "Total%" "Total") @@ -62,17 +76,20 @@ (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) - (Math/round (/ total grand-total-time 0.01)) + (perc total total-time) (ft total)))) - (printf s-pattern "" "" "" "" "" "" (ft grand-total-time)))))) + (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))))))) (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 (keyword (str *ns*) (clojure.core/name name))] + (let [name (prepare-name name)] `(binding [*plog* (atom {})] (let [result# (do ~@body)] (~log-fn ~name (plog-stats @*plog*)) @@ -97,7 +114,7 @@ (str "Profiling: " (fqname name#)) (str "\n" (plog-table stats#)))) ~name - ~@body) + (p :meta/total ~@body)) (do ~@body))) (defmacro sampling-profile @@ -110,6 +127,7 @@ (comment (profile :info :Sleepy-threads + (Thread/sleep 100) ; Unaccounted (p :1ms (Thread/sleep 1)) (p :2s (Thread/sleep 2000)) (p :50ms (Thread/sleep 50)) @@ -121,8 +139,8 @@ (defn my-fn [] (let [nums (vec (range 1000))] - (+ (p :fast-thread (Thread/sleep 1) 10) - (p :slow-thread (Thread/sleep 2) 32) + (+ (p :fast-sleep (Thread/sleep 1) 10) + (p :slow-sleep (Thread/sleep 2) 32) (p :add (reduce + nums)) (p :sub (reduce - nums)) (p :mult (reduce * nums))