Merge branch 'dev'

CHANGELOG.md

@@ -1,3 +1,8 @@
+## v3.1.6 / 2014 Mar 16
+
+ * [#56] FIX: `defnp`/`p` head retention issue (kyptin).
+
+
 ## v3.1.5 / 2014 Mar 15
 
  * FIX: `profiling/p*` was defined incorrectly (kyptin).

README.md

@@ -1,7 +1,7 @@
 **[API docs][]** | **[CHANGELOG][]** | [other Clojure libs][] | [Twitter][] | [contact/contributing](#contact--contributing) | current ([semantic][]) version:
 
 ```clojure
-[com.taoensso/timbre "3.1.5"] ; 3.x is a non-breaking upgrade - see CHANGELOG for details
+[com.taoensso/timbre "3.1.6"] ; 3.x is a non-breaking upgrade - see CHANGELOG for details
 ```
 
 Appender authors: please see [here](https://github.com/ptaoussanis/timbre/issues/41) about migrating Timbre 2.x appenders to 3.x's recommended style.
@@ -30,7 +30,7 @@ Logging with Java can be maddeningly, unnecessarily hard. Particularly if all yo
 Add the necessary dependency to your [Leiningen][] `project.clj` and use the supplied ns-import helper:
 
 ```clojure
-[com.taoensso/timbre "3.1.5"] ; project.clj
+[com.taoensso/timbre "3.1.6"] ; project.clj
 
 (ns my-app (:require [taoensso.timbre :as timbre])) ; Your ns
 (timbre/refer-timbre) ; Provides useful Timbre aliases in this ns

project.clj

@@ -1,4 +1,4 @@
-(defproject com.taoensso/timbre "3.1.5"
+(defproject com.taoensso/timbre "3.1.6"
   :author "Peter Taoussanis <https://www.taoensso.com>"
   :description "Clojure logging & profiling library"
   :url "https://github.com/ptaoussanis/timbre"

src/taoensso/timbre/profiling.clj

@@ -12,6 +12,21 @@
 (comment (map #(fq-keyword %) ["foo" :foo :foo/bar]))
 
 (def ^:dynamic *pdata* "{::pid [time1 time2 ...]}" nil)
+(defmacro pspy
+  "Profile spy. When in the context of a *pdata* binding, records execution time
+  of named body. Always returns the body's result."
+  ;; Note: do NOT implement as `(pspy* ~id (fn [] ~@body))`. The fn wrapping
+  ;; can cause unnecessary lazy seq head retention, Ref. http://goo.gl/42Vxph.
+  [id & body]
+  `(if-not *pdata* (do ~@body)
+     (let [id# (fq-keyword ~id)
+           t0# (System/nanoTime)]
+       (try (do ~@body)
+            (finally
+              (let [t-elapsed# (- (System/nanoTime) t0#)]
+                (swap! *pdata* #(assoc % id# (conj (% id# []) t-elapsed#)))))))))
+
+(defmacro p [id & body] `(pspy ~id ~@body)) ; Alias
 
 (defn pspy* [id f]
   (if-not *pdata* (f)
@@ -22,19 +37,12 @@
              (let [t-elapsed (- (System/nanoTime) t0)]
                (swap! *pdata* #(assoc % id (conj (% id []) t-elapsed)))))))))
 
-(defmacro pspy
-  "Profile spy. When in the context of a *pdata* binding, records execution time
-  of named body. Always returns the body's result."
-  [id & body] `(pspy* ~id (fn [] ~@body)))
-
-;;; Aliases
-(def p* pspy*)
-(defmacro p [id & body] `(pspy ~id ~@body))
+(def p* pspy*) ; Alias
 
 (comment
-  (time (dotimes [_ 1000000])) ; ~20ms
-  ;; Note that times are ~= for `pspy` as a pure macro and as a `pspy*` fn caller:
-  (time (dotimes [_ 1000000] (pspy :foo))) ; ~300ms
+  (binding [*pdata* {}])
+  (time (dotimes [_ 1000000])) ; ~3ms
+  (time (dotimes [_ 1000000] (pspy :foo))) ; ~65ms (^:dynamic bound >= once!)
   )
 
 (declare pdata-stats format-pdata)
@@ -43,7 +51,7 @@
   `(if-not (timbre/logging-enabled? ~level ~(str *ns*))
      {:result (do ~@body)}
      (binding [*pdata* (atom {})]
-       {:result (p ::clock-time ~@body)
+       {:result (pspy ::clock-time ~@body)
         :stats  (pdata-stats @*pdata*)})))
 
 (defmacro profile
@@ -127,8 +135,8 @@
         prepost-map (when (and (map? (first sigs)) (next sigs)) (first sigs))
         body (if prepost-map (next sigs) sigs)]
     `(defn ~name ~params ~prepost-map
-       (p ~(clojure.core/name name)
-          ~@body))))
+       (pspy ~(clojure.core/name name)
+             ~@body))))
 
 (comment (defnp foo "Docstring "[x] "boo" (* x x))
          (macroexpand '(defnp foo "Docstring "[x] "boo" (* x x)))