|
rlm@10
|
1 ;;; profile.clj: simple code profiling & timing
|
|
rlm@10
|
2
|
|
rlm@10
|
3 ;; by Stuart Sierra, http://stuartsierra.com/
|
|
rlm@10
|
4 ;; May 9, 2009
|
|
rlm@10
|
5
|
|
rlm@10
|
6 ;; Copyright (c) Stuart Sierra, 2009. All rights reserved. The use
|
|
rlm@10
|
7 ;; and distribution terms for this software are covered by the Eclipse
|
|
rlm@10
|
8 ;; Public License 1.0 (http://opensource.org/licenses/eclipse-1.0.php)
|
|
rlm@10
|
9 ;; which can be found in the file epl-v10.html at the root of this
|
|
rlm@10
|
10 ;; distribution. By using this software in any fashion, you are
|
|
rlm@10
|
11 ;; agreeing to be bound by the terms of this license. You must not
|
|
rlm@10
|
12 ;; remove this notice, or any other, from this software.
|
|
rlm@10
|
13
|
|
rlm@10
|
14
|
|
rlm@10
|
15 (ns ^{:author "Stuart Sierra"
|
|
rlm@10
|
16 :doc "Simple code profiling & timing measurement.
|
|
rlm@10
|
17
|
|
rlm@10
|
18 Wrap any section of code in the prof macro, giving it a name, like this:
|
|
rlm@10
|
19
|
|
rlm@10
|
20 (defn my-function [x y]
|
|
rlm@10
|
21 (let [sum (prof :addition (+ x y))
|
|
rlm@10
|
22 product (prof :multiplication (* x y))]
|
|
rlm@10
|
23 [sum product]))
|
|
rlm@10
|
24
|
|
rlm@10
|
25 The run your code in the profile macro, like this:
|
|
rlm@10
|
26
|
|
rlm@10
|
27 (profile (dotimes [i 10000] (my-function 3 4)))
|
|
rlm@10
|
28
|
|
rlm@10
|
29 Which prints a report for each named section of code:
|
|
rlm@10
|
30
|
|
rlm@10
|
31 Name mean min max count sum
|
|
rlm@10
|
32 addition 265 0 37000 10000 2655000
|
|
rlm@10
|
33 multiplication 274 0 53000 10000 2747000
|
|
rlm@10
|
34
|
|
rlm@10
|
35 Times are measured in nanoseconds, to the maximum precision available
|
|
rlm@10
|
36 under the JVM. See the function documentation for more details.
|
|
rlm@10
|
37 "}
|
|
rlm@10
|
38 clojure.contrib.profile)
|
|
rlm@10
|
39
|
|
rlm@10
|
40 (def *profile-data* nil)
|
|
rlm@10
|
41
|
|
rlm@10
|
42 (def ^{:doc "Set this to false before loading/compiling to omit
|
|
rlm@10
|
43 profiling code."} *enable-profiling* true)
|
|
rlm@10
|
44
|
|
rlm@10
|
45 (defmacro prof
|
|
rlm@10
|
46 "If *enable-profiling* is true, wraps body in profiling code.
|
|
rlm@10
|
47 Returns the result of body. Profile timings will be stored in
|
|
rlm@10
|
48 *profile-data* using name, which must be a keyword, as the key.
|
|
rlm@10
|
49 Timings are measured with System/nanoTime."
|
|
rlm@10
|
50 [name & body]
|
|
rlm@10
|
51 (assert (keyword? name))
|
|
rlm@10
|
52 (if *enable-profiling*
|
|
rlm@10
|
53 `(if *profile-data*
|
|
rlm@10
|
54 (let [start-time# (System/nanoTime)
|
|
rlm@10
|
55 value# (do ~@body)
|
|
rlm@10
|
56 elapsed# (- (System/nanoTime) start-time#)]
|
|
rlm@10
|
57 (swap! *profile-data* assoc ~name
|
|
rlm@10
|
58 (conj (get @*profile-data* ~name) elapsed#))
|
|
rlm@10
|
59 value#)
|
|
rlm@10
|
60 ~@body)
|
|
rlm@10
|
61 `(do ~@body)))
|
|
rlm@10
|
62
|
|
rlm@10
|
63 (defmacro with-profile-data
|
|
rlm@10
|
64 "Executes body with *profile-data* bound to an atom of a new map.
|
|
rlm@10
|
65 Returns the raw profile data as a map. Keys in the map are profile
|
|
rlm@10
|
66 names (keywords), and values are lists of elapsed time, in
|
|
rlm@10
|
67 nanoseconds."
|
|
rlm@10
|
68 [& body]
|
|
rlm@10
|
69 `(binding [*profile-data* (atom {})]
|
|
rlm@10
|
70 ~@body
|
|
rlm@10
|
71 @*profile-data*))
|
|
rlm@10
|
72
|
|
rlm@10
|
73 (defn summarize
|
|
rlm@10
|
74 "Takes the raw data returned by with-profile-data and returns a map
|
|
rlm@10
|
75 from names to summary statistics. Each value in the map will look
|
|
rlm@10
|
76 like:
|
|
rlm@10
|
77
|
|
rlm@10
|
78 {:mean ..., :min ..., :max ..., :count ..., :sum ...}
|
|
rlm@10
|
79
|
|
rlm@10
|
80 :mean, :min, and :max are how long the profiled section took to run,
|
|
rlm@10
|
81 in nanoseconds. :count is the total number of times the profiled
|
|
rlm@10
|
82 section was executed. :sum is the total amount of time spent in the
|
|
rlm@10
|
83 profiled section, in nanoseconds."
|
|
rlm@10
|
84 [profile-data]
|
|
rlm@10
|
85 (reduce (fn [m [k v]]
|
|
rlm@10
|
86 (let [cnt (count v)
|
|
rlm@10
|
87 sum (reduce + v)]
|
|
rlm@10
|
88 (assoc m k {:mean (int (/ sum cnt))
|
|
rlm@10
|
89 :min (apply min v)
|
|
rlm@10
|
90 :max (apply max v)
|
|
rlm@10
|
91 :count cnt
|
|
rlm@10
|
92 :sum sum})))
|
|
rlm@10
|
93 {} profile-data))
|
|
rlm@10
|
94
|
|
rlm@10
|
95 (defn print-summary
|
|
rlm@10
|
96 "Prints a table of the results returned by summarize."
|
|
rlm@10
|
97 [profile-summary]
|
|
rlm@10
|
98 (let [name-width (apply max 1 (map (comp count name) (keys profile-summary)))
|
|
rlm@10
|
99 fmt-string (str "%" name-width "s %8d %8d %8d %8d %8d%n")]
|
|
rlm@10
|
100 (printf (.replace fmt-string \d \s)
|
|
rlm@10
|
101 "Name" "mean" "min" "max" "count" "sum")
|
|
rlm@10
|
102 (doseq [k (sort (keys profile-summary))]
|
|
rlm@10
|
103 (let [v (get profile-summary k)]
|
|
rlm@10
|
104 (printf fmt-string (name k) (:mean v) (:min v) (:max v) (:count v) (:sum v))))))
|
|
rlm@10
|
105
|
|
rlm@10
|
106 (defmacro profile
|
|
rlm@10
|
107 "Runs body with profiling enabled, then prints a summary of
|
|
rlm@10
|
108 results. Returns nil."
|
|
rlm@10
|
109 [& body]
|
|
rlm@10
|
110 `(print-summary (summarize (with-profile-data (do ~@body)))))
|
