Mercurial > lasercutter

comparison src/clojure/contrib/profile.clj @ 10:ef7dbbd6452c

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
added clojure source goodness
author Robert McIntyre <rlm@mit.edu>
date Sat, 21 Aug 2010 06:25:44 -0400
parents
children
comparison
equal deleted inserted replaced
9:35cf337adfcf 10:ef7dbbd6452c
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)))))