1.1 --- /dev/null	Thu Jan 01 00:00:00 1970 +0000
     1.2 +++ b/src/clojure/contrib/profile.clj	Sat Aug 21 06:25:44 2010 -0400
     1.3 @@ -0,0 +1,110 @@
     1.4 +;;; profile.clj: simple code profiling & timing
     1.5 +
     1.6 +;; by Stuart Sierra, http://stuartsierra.com/
     1.7 +;; May 9, 2009
     1.8 +
     1.9 +;; Copyright (c) Stuart Sierra, 2009. All rights reserved.  The use
    1.10 +;; and distribution terms for this software are covered by the Eclipse
    1.11 +;; Public License 1.0 (http://opensource.org/licenses/eclipse-1.0.php)
    1.12 +;; which can be found in the file epl-v10.html at the root of this
    1.13 +;; distribution.  By using this software in any fashion, you are
    1.14 +;; agreeing to be bound by the terms of this license.  You must not
    1.15 +;; remove this notice, or any other, from this software.
    1.16 +
    1.17 +
    1.18 +(ns ^{:author "Stuart Sierra"
    1.19 +       :doc "Simple code profiling & timing measurement.
    1.20 +
    1.21 +Wrap any section of code in the prof macro, giving it a name, like this:
    1.22 +
    1.23 +       (defn my-function [x y]
    1.24 +         (let [sum (prof :addition (+ x y))
    1.25 +               product (prof :multiplication (* x y))]
    1.26 +           [sum product]))
    1.27 +
    1.28 +The run your code in the profile macro, like this:
    1.29 +
    1.30 +       (profile (dotimes [i 10000] (my-function 3 4)))
    1.31 +
    1.32 +Which prints a report for each named section of code:
    1.33 +
    1.34 +          Name      mean       min       max     count       sum
    1.35 +      addition       265         0     37000     10000   2655000
    1.36 +multiplication       274         0     53000     10000   2747000
    1.37 +
    1.38 +Times are measured in nanoseconds, to the maximum precision available
    1.39 +under the JVM.  See the function documentation for more details.
    1.40 +"}
    1.41 +  clojure.contrib.profile)
    1.42 +
    1.43 +(def *profile-data* nil)
    1.44 +
    1.45 +(def ^{:doc "Set this to false before loading/compiling to omit
    1.46 +profiling code."}  *enable-profiling* true)
    1.47 +
    1.48 +(defmacro prof
    1.49 +  "If *enable-profiling* is true, wraps body in profiling code.
    1.50 +  Returns the result of body. Profile timings will be stored in
    1.51 +  *profile-data* using name, which must be a keyword, as the key.
    1.52 +  Timings are measured with System/nanoTime."
    1.53 +  [name & body]
    1.54 +  (assert (keyword? name))
    1.55 +  (if *enable-profiling*
    1.56 +    `(if *profile-data*
    1.57 +       (let [start-time# (System/nanoTime)
    1.58 +             value# (do ~@body)
    1.59 +             elapsed# (- (System/nanoTime) start-time#)]
    1.60 +         (swap! *profile-data* assoc ~name
    1.61 +                (conj (get @*profile-data* ~name) elapsed#))
    1.62 +         value#)
    1.63 +       ~@body)
    1.64 +    `(do ~@body)))
    1.65 +
    1.66 +(defmacro with-profile-data
    1.67 +  "Executes body with *profile-data* bound to an atom of a new map.
    1.68 +  Returns the raw profile data as a map.  Keys in the map are profile
    1.69 +  names (keywords), and values are lists of elapsed time, in
    1.70 +  nanoseconds."
    1.71 +  [& body]
    1.72 +  `(binding [*profile-data* (atom {})]
    1.73 +     ~@body
    1.74 +     @*profile-data*))
    1.75 +
    1.76 +(defn summarize
    1.77 +  "Takes the raw data returned by with-profile-data and returns a map
    1.78 +  from names to summary statistics.  Each value in the map will look
    1.79 +  like:
    1.80 +
    1.81 +     {:mean ..., :min ..., :max ..., :count ..., :sum ...}
    1.82 +
    1.83 +  :mean, :min, and :max are how long the profiled section took to run,
    1.84 +  in nanoseconds.  :count is the total number of times the profiled
    1.85 +  section was executed.  :sum is the total amount of time spent in the
    1.86 +  profiled section, in nanoseconds."
    1.87 +  [profile-data]
    1.88 +  (reduce (fn [m [k v]]
    1.89 +            (let [cnt (count v)
    1.90 +                  sum (reduce + v)]
    1.91 +              (assoc m k {:mean (int (/ sum cnt))
    1.92 +                          :min (apply min v)
    1.93 +                          :max (apply max v)
    1.94 +                          :count cnt
    1.95 +                          :sum sum})))
    1.96 +          {} profile-data))
    1.97 +
    1.98 +(defn print-summary
    1.99 +  "Prints a table of the results returned by summarize."
   1.100 +  [profile-summary]
   1.101 +  (let [name-width (apply max 1 (map (comp count name) (keys profile-summary)))
   1.102 +        fmt-string (str "%" name-width "s  %8d  %8d  %8d  %8d  %8d%n")]
   1.103 +    (printf (.replace fmt-string \d \s)
   1.104 +            "Name" "mean" "min" "max" "count" "sum")
   1.105 +    (doseq [k (sort (keys profile-summary))]
   1.106 +      (let [v (get profile-summary k)]
   1.107 +        (printf fmt-string (name k) (:mean v) (:min v) (:max v) (:count v) (:sum v))))))
   1.108 +
   1.109 +(defmacro profile
   1.110 +  "Runs body with profiling enabled, then prints a summary of
   1.111 +  results.  Returns nil."
   1.112 +  [& body]
   1.113 +  `(print-summary (summarize (with-profile-data (do ~@body)))))