rlm@10: ;;; profile.clj: simple code profiling & timing
rlm@10: 
rlm@10: ;; by Stuart Sierra, http://stuartsierra.com/
rlm@10: ;; May 9, 2009
rlm@10: 
rlm@10: ;; Copyright (c) Stuart Sierra, 2009. All rights reserved.  The use
rlm@10: ;; and distribution terms for this software are covered by the Eclipse
rlm@10: ;; Public License 1.0 (http://opensource.org/licenses/eclipse-1.0.php)
rlm@10: ;; which can be found in the file epl-v10.html at the root of this
rlm@10: ;; distribution.  By using this software in any fashion, you are
rlm@10: ;; agreeing to be bound by the terms of this license.  You must not
rlm@10: ;; remove this notice, or any other, from this software.
rlm@10: 
rlm@10: 
rlm@10: (ns ^{:author "Stuart Sierra"
rlm@10:        :doc "Simple code profiling & timing measurement.
rlm@10: 
rlm@10: Wrap any section of code in the prof macro, giving it a name, like this:
rlm@10: 
rlm@10:        (defn my-function [x y]
rlm@10:          (let [sum (prof :addition (+ x y))
rlm@10:                product (prof :multiplication (* x y))]
rlm@10:            [sum product]))
rlm@10: 
rlm@10: The run your code in the profile macro, like this:
rlm@10: 
rlm@10:        (profile (dotimes [i 10000] (my-function 3 4)))
rlm@10: 
rlm@10: Which prints a report for each named section of code:
rlm@10: 
rlm@10:           Name      mean       min       max     count       sum
rlm@10:       addition       265         0     37000     10000   2655000
rlm@10: multiplication       274         0     53000     10000   2747000
rlm@10: 
rlm@10: Times are measured in nanoseconds, to the maximum precision available
rlm@10: under the JVM.  See the function documentation for more details.
rlm@10: "}
rlm@10:   clojure.contrib.profile)
rlm@10: 
rlm@10: (def *profile-data* nil)
rlm@10: 
rlm@10: (def ^{:doc "Set this to false before loading/compiling to omit
rlm@10: profiling code."}  *enable-profiling* true)
rlm@10: 
rlm@10: (defmacro prof
rlm@10:   "If *enable-profiling* is true, wraps body in profiling code.
rlm@10:   Returns the result of body. Profile timings will be stored in
rlm@10:   *profile-data* using name, which must be a keyword, as the key.
rlm@10:   Timings are measured with System/nanoTime."
rlm@10:   [name & body]
rlm@10:   (assert (keyword? name))
rlm@10:   (if *enable-profiling*
rlm@10:     `(if *profile-data*
rlm@10:        (let [start-time# (System/nanoTime)
rlm@10:              value# (do ~@body)
rlm@10:              elapsed# (- (System/nanoTime) start-time#)]
rlm@10:          (swap! *profile-data* assoc ~name
rlm@10:                 (conj (get @*profile-data* ~name) elapsed#))
rlm@10:          value#)
rlm@10:        ~@body)
rlm@10:     `(do ~@body)))
rlm@10: 
rlm@10: (defmacro with-profile-data
rlm@10:   "Executes body with *profile-data* bound to an atom of a new map.
rlm@10:   Returns the raw profile data as a map.  Keys in the map are profile
rlm@10:   names (keywords), and values are lists of elapsed time, in
rlm@10:   nanoseconds."
rlm@10:   [& body]
rlm@10:   `(binding [*profile-data* (atom {})]
rlm@10:      ~@body
rlm@10:      @*profile-data*))
rlm@10: 
rlm@10: (defn summarize
rlm@10:   "Takes the raw data returned by with-profile-data and returns a map
rlm@10:   from names to summary statistics.  Each value in the map will look
rlm@10:   like:
rlm@10: 
rlm@10:      {:mean ..., :min ..., :max ..., :count ..., :sum ...}
rlm@10: 
rlm@10:   :mean, :min, and :max are how long the profiled section took to run,
rlm@10:   in nanoseconds.  :count is the total number of times the profiled
rlm@10:   section was executed.  :sum is the total amount of time spent in the
rlm@10:   profiled section, in nanoseconds."
rlm@10:   [profile-data]
rlm@10:   (reduce (fn [m [k v]]
rlm@10:             (let [cnt (count v)
rlm@10:                   sum (reduce + v)]
rlm@10:               (assoc m k {:mean (int (/ sum cnt))
rlm@10:                           :min (apply min v)
rlm@10:                           :max (apply max v)
rlm@10:                           :count cnt
rlm@10:                           :sum sum})))
rlm@10:           {} profile-data))
rlm@10: 
rlm@10: (defn print-summary
rlm@10:   "Prints a table of the results returned by summarize."
rlm@10:   [profile-summary]
rlm@10:   (let [name-width (apply max 1 (map (comp count name) (keys profile-summary)))
rlm@10:         fmt-string (str "%" name-width "s  %8d  %8d  %8d  %8d  %8d%n")]
rlm@10:     (printf (.replace fmt-string \d \s)
rlm@10:             "Name" "mean" "min" "max" "count" "sum")
rlm@10:     (doseq [k (sort (keys profile-summary))]
rlm@10:       (let [v (get profile-summary k)]
rlm@10:         (printf fmt-string (name k) (:mean v) (:min v) (:max v) (:count v) (:sum v))))))
rlm@10: 
rlm@10: (defmacro profile
rlm@10:   "Runs body with profiling enabled, then prints a summary of
rlm@10:   results.  Returns nil."
rlm@10:   [& body]
rlm@10:   `(print-summary (summarize (with-profile-data (do ~@body)))))