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