Mercurial > lasercutter

     1 ;;; profile.clj: simple code profiling & timing

     2 

     3 ;; by Stuart Sierra, http://stuartsierra.com/

     4 ;; May 9, 2009

     5 

     6 ;; Copyright (c) Stuart Sierra, 2009. All rights reserved.  The use

     7 ;; and distribution terms for this software are covered by the Eclipse

     8 ;; Public License 1.0 (http://opensource.org/licenses/eclipse-1.0.php)

     9 ;; which can be found in the file epl-v10.html at the root of this

    10 ;; distribution.  By using this software in any fashion, you are

    11 ;; agreeing to be bound by the terms of this license.  You must not

    12 ;; remove this notice, or any other, from this software.

    13 

    14 

    15 (ns ^{:author "Stuart Sierra"

    16        :doc "Simple code profiling & timing measurement.

    17 

    18 Wrap any section of code in the prof macro, giving it a name, like this:

    19 

    20        (defn my-function [x y]

    21          (let [sum (prof :addition (+ x y))

    22                product (prof :multiplication (* x y))]

    23            [sum product]))

    24 

    25 The run your code in the profile macro, like this:

    26 

    27        (profile (dotimes [i 10000] (my-function 3 4)))

    28 

    29 Which prints a report for each named section of code:

    30 

    31           Name      mean       min       max     count       sum

    32       addition       265         0     37000     10000   2655000

    33 multiplication       274         0     53000     10000   2747000

    34 

    35 Times are measured in nanoseconds, to the maximum precision available

    36 under the JVM.  See the function documentation for more details.

    37 "}

    38   clojure.contrib.profile)

    39 

    40 (def *profile-data* nil)

    41 

    42 (def ^{:doc "Set this to false before loading/compiling to omit

    43 profiling code."}  *enable-profiling* true)

    44 

    45 (defmacro prof

    46   "If *enable-profiling* is true, wraps body in profiling code.

    47   Returns the result of body. Profile timings will be stored in

    48   *profile-data* using name, which must be a keyword, as the key.

    49   Timings are measured with System/nanoTime."

    50   [name & body]

    51   (assert (keyword? name))

    52   (if *enable-profiling*

    53     `(if *profile-data*

    54        (let [start-time# (System/nanoTime)

    55              value# (do ~@body)

    56              elapsed# (- (System/nanoTime) start-time#)]

    57          (swap! *profile-data* assoc ~name

    58                 (conj (get @*profile-data* ~name) elapsed#))

    59          value#)

    60        ~@body)

    61     `(do ~@body)))

    62 

    63 (defmacro with-profile-data

    64   "Executes body with *profile-data* bound to an atom of a new map.

    65   Returns the raw profile data as a map.  Keys in the map are profile

    66   names (keywords), and values are lists of elapsed time, in

    67   nanoseconds."

    68   [& body]

    69   `(binding [*profile-data* (atom {})]

    70      ~@body

    71      @*profile-data*))

    72 

    73 (defn summarize

    74   "Takes the raw data returned by with-profile-data and returns a map

    75   from names to summary statistics.  Each value in the map will look

    76   like:

    77 

    78      {:mean ..., :min ..., :max ..., :count ..., :sum ...}

    79 

    80   :mean, :min, and :max are how long the profiled section took to run,

    81   in nanoseconds.  :count is the total number of times the profiled

    82   section was executed.  :sum is the total amount of time spent in the

    83   profiled section, in nanoseconds."

    84   [profile-data]

    85   (reduce (fn [m [k v]]

    86             (let [cnt (count v)

    87                   sum (reduce + v)]

    88               (assoc m k {:mean (int (/ sum cnt))

    89                           :min (apply min v)

    90                           :max (apply max v)

    91                           :count cnt

    92                           :sum sum})))

    93           {} profile-data))

    94 

    95 (defn print-summary

    96   "Prints a table of the results returned by summarize."

    97   [profile-summary]

    98   (let [name-width (apply max 1 (map (comp count name) (keys profile-summary)))

    99         fmt-string (str "%" name-width "s  %8d  %8d  %8d  %8d  %8d%n")]

   100     (printf (.replace fmt-string \d \s)

   101             "Name" "mean" "min" "max" "count" "sum")

   102     (doseq [k (sort (keys profile-summary))]

   103       (let [v (get profile-summary k)]

   104         (printf fmt-string (name k) (:mean v) (:min v) (:max v) (:count v) (:sum v))))))

   105 

   106 (defmacro profile

   107   "Runs body with profiling enabled, then prints a summary of

   108   results.  Returns nil."

   109   [& body]

   110   `(print-summary (summarize (with-profile-data (do ~@body)))))
author	Robert McIntyre <rlm@mit.edu>
date	Sat, 21 Aug 2010 06:25:44 -0400
parents
children