From 49830fe798e79a7499d64c6befa0dd7952403e98 Mon Sep 17 00:00:00 2001
From: Peter Taoussanis <ptaoussanis@gmail.com>
Date: Thu, 23 Jun 2016 16:29:14 +0700
Subject: [PATCH] Profiling: add experimental low-level `profiled` util

---
 src/taoensso/timbre/profiling.clj | 41 ++++++++++++++++++++++---------
 1 file changed, 30 insertions(+), 11 deletions(-)

diff --git a/src/taoensso/timbre/profiling.clj b/src/taoensso/timbre/profiling.clj
index 625a30e..feebd14 100644
--- a/src/taoensso/timbre/profiling.clj
+++ b/src/taoensso/timbre/profiling.clj
@@ -201,8 +201,9 @@
       `(let [pdata# (-pdata-proxy)]
          (if pdata#
            (let [t0# (System/nanoTime)
-                 result# (do ~@body)]
-             (-capture-time! pdata# ~id (- (System/nanoTime) t0#))
+                 result# (do ~@body)
+                 t1# (System/nanoTime)]
+             (-capture-time! pdata# ~id (- t1# t0#))
              result#)
            (do ~@body))))))
 
@@ -210,6 +211,26 @@
 
 (comment (macroexpand '(p :foo (+ 4 2))))
 
+(defmacro profiled
+  "Experimental, subject to change!
+  Low-level profiling util. Executes expr with thread-local profiling
+  enabled, then executes body with `[<stats> <expr-result>]` binding, e.g:
+    (profiled \"foo\" [stats result] (do (println stats) result))"
+  [expr-to-profile params & body]
+  (assert (vector?    params))
+  (assert (= 2 (count params)))
+  (let [[stats result] params]
+   `(try
+      (-pdata-proxy (-new-pdata))
+      (let [t0# (System/nanoTime)
+            ~result ~expr-to-profile
+            t1# (System/nanoTime)
+            ~stats (-compile-final-stats! (- t1# t0#))]
+        (do ~@body))
+      (finally (-pdata-proxy nil)))))
+
+(comment (profiled (p :foo "foo") [stats result] [stats result]))
+
 (defmacro profile
   "When logging is enabled, executes named body with thread-local profiling
   enabled and logs profiling stats. Always returns body's result."
@@ -218,21 +239,18 @@
     (if elide-profiling?
       `(do ~@body)
       `(if (timbre/log? ~level ~(str *ns*)) ; Runtime check
-         (try
-           (-pdata-proxy (-new-pdata))
-           (let [t0# (System/nanoTime)
-                 result# (do ~@body)
-                 stats# (-compile-final-stats! (- (System/nanoTime) t0#))
-                 stats-str# (-format-stats stats#)]
+         (profiled (do ~@body) [stats# result#]
+           (let [stats-str# (-format-stats stats#)]
              (timbre/log! ~level :p
                ["Profiling: " ~id "\n" stats-str#]
                {:?base-data
                 {:profile-stats     stats#
                  :profile-stats-str stats-str#}})
-             result#)
-           (finally (-pdata-proxy nil)))
+             result#))
          (do ~@body)))))
 
+(comment (profile :info :foo "foo"))
+
 (defmacro sampling-profile
   "Like `profile`, but only enables profiling with given probability."
   [level probability id & body]
@@ -329,6 +347,7 @@
          (p :div  (reduce / nums)))))
 
   (profile :info :Arithmetic (dotimes [n 100] (my-fn)))
-  (profile :info :high-n     (dotimes [n 1e5] (p :nil nil))) ; ~19ms
+  (profile :info :high-n     (dotimes [n 1e5] (p :nil nil))) ; ~20ms
   (profile :info :high-n     (dotimes [n 1e6] (p :nil nil))) ; ~116ms
+  (profiled (dotimes [n 1e6] (p :nil nil)) [stats result] [stats result])
   (sampling-profile :info 0.5 :sampling-test (p :string "Hello!")))