31 |
with-benchmark-prefix with-benchmark-prefix* current-benchmark-prefix |
with-benchmark-prefix with-benchmark-prefix* current-benchmark-prefix |
32 |
format-benchmark-name |
format-benchmark-name |
33 |
|
|
34 |
|
;; Computing timing results |
35 |
|
benchmark-time-base |
36 |
|
benchmark-total-time benchmark-user-time benchmark-system-time |
37 |
|
benchmark-frame-time benchmark-core-time |
38 |
|
benchmark-user-time\interpreter benchmark-core-time\interpreter |
39 |
|
|
40 |
;; Reporting results in various ways. |
;; Reporting results in various ways. |
41 |
register-reporter unregister-reporter reporter-registered? |
register-reporter unregister-reporter reporter-registered? |
42 |
make-log-reporter |
make-log-reporter |
43 |
full-reporter |
full-reporter |
44 |
user-reporter)) |
user-reporter)) |
45 |
|
|
46 |
|
|
47 |
|
;;;; If you're using Emacs's Scheme mode: |
48 |
|
;;;; (put 'with-benchmark-prefix 'scheme-indent-function 1) |
49 |
|
;;;; (put 'benchmark 'scheme-indent-function 1) |
50 |
|
|
51 |
|
|
52 |
|
;;;; CORE FUNCTIONS |
53 |
|
;;;; |
54 |
|
;;;; The function (run-benchmark name iterations thunk) is the heart of the |
55 |
|
;;;; benchmarking environment. The first parameter NAME is a unique name for |
56 |
|
;;;; the benchmark to be executed (for an explanation of this parameter see |
57 |
|
;;;; below under ;;;; NAMES. The second parameter ITERATIONS is a positive |
58 |
|
;;;; integer value that indicates how often the thunk shall be executed (for |
59 |
|
;;;; an explanation of how iteration counts should be used, see below under |
60 |
|
;;;; ;;;; ITERATION COUNTS). For example: |
61 |
|
;;;; |
62 |
|
;;;; (run-benchmark "small integer addition" 100000 (lambda () (+ 1 1))) |
63 |
|
;;;; |
64 |
|
;;;; This will run the function (lambda () (+ 1 1)) a 100000 times (the |
65 |
|
;;;; iteration count can, however be scaled. See below for details). Some |
66 |
|
;;;; different time data for running the thunk for the given number of |
67 |
|
;;;; iterations is measured and reported. |
68 |
|
;;;; |
69 |
|
;;;; Convenience macro |
70 |
|
;;;; |
71 |
|
;;;; * (benchmark name iterations body) is a short form for |
72 |
|
;;;; (run-benchmark name iterations (lambda () body)) |
73 |
|
|
74 |
|
|
75 |
|
;;;; NAMES |
76 |
|
;;;; |
77 |
|
;;;; Every benchmark in the benchmark suite has a unique name to be able to |
78 |
|
;;;; compare the results of individual benchmarks across several runs of the |
79 |
|
;;;; benchmark suite. |
80 |
|
;;;; |
81 |
|
;;;; A benchmark name is a list of printable objects. For example: |
82 |
|
;;;; ("ports.scm" "file" "read and write back list of strings") |
83 |
|
;;;; ("ports.scm" "pipe" "read") |
84 |
|
;;;; |
85 |
|
;;;; Benchmark names may contain arbitrary objects, but they always have |
86 |
|
;;;; the following properties: |
87 |
|
;;;; - Benchmark names can be compared with EQUAL?. |
88 |
|
;;;; - Benchmark names can be reliably stored and retrieved with the standard |
89 |
|
;;;; WRITE and READ procedures; doing so preserves their identity. |
90 |
|
;;;; |
91 |
|
;;;; For example: |
92 |
|
;;;; |
93 |
|
;;;; (benchmark "simple addition" 100000 (+ 2 2)) |
94 |
|
;;;; |
95 |
|
;;;; In that case, the benchmark name is the list ("simple addition"). |
96 |
|
;;;; |
97 |
|
;;;; The WITH-BENCHMARK-PREFIX syntax and WITH-BENCHMARK-PREFIX* procedure |
98 |
|
;;;; establish a prefix for the names of all benchmarks whose results are |
99 |
|
;;;; reported within their dynamic scope. For example: |
100 |
|
;;;; |
101 |
|
;;;; (begin |
102 |
|
;;;; (with-benchmark-prefix "basic arithmetic" |
103 |
|
;;;; (benchmark "addition" 100000 (+ 2 2)) |
104 |
|
;;;; (benchmark "subtraction" 100000 (- 4 2))) |
105 |
|
;;;; (benchmark "multiplication" 100000 (* 2 2)))) |
106 |
|
;;;; |
107 |
|
;;;; In that example, the three benchmark names are: |
108 |
|
;;;; ("basic arithmetic" "addition"), |
109 |
|
;;;; ("basic arithmetic" "subtraction"), and |
110 |
|
;;;; ("multiplication"). |
111 |
|
;;;; |
112 |
|
;;;; WITH-BENCHMARK-PREFIX can be nested. Each WITH-BENCHMARK-PREFIX |
113 |
|
;;;; postpends a new element to the current prefix: |
114 |
|
;;;; |
115 |
|
;;;; (with-benchmark-prefix "arithmetic" |
116 |
|
;;;; (with-benchmark-prefix "addition" |
117 |
|
;;;; (benchmark "integer" 100000 (+ 2 2)) |
118 |
|
;;;; (benchmark "complex" 100000 (+ 2+3i 4+5i))) |
119 |
|
;;;; (with-benchmark-prefix "subtraction" |
120 |
|
;;;; (benchmark "integer" 100000 (- 2 2)) |
121 |
|
;;;; (benchmark "complex" 100000 (- 2+3i 1+2i)))) |
122 |
|
;;;; |
123 |
|
;;;; The four benchmark names here are: |
124 |
|
;;;; ("arithmetic" "addition" "integer") |
125 |
|
;;;; ("arithmetic" "addition" "complex") |
126 |
|
;;;; ("arithmetic" "subtraction" "integer") |
127 |
|
;;;; ("arithmetic" "subtraction" "complex") |
128 |
|
;;;; |
129 |
|
;;;; To print a name for a human reader, we DISPLAY its elements, |
130 |
|
;;;; separated by ": ". So, the last set of benchmark names would be |
131 |
|
;;;; reported as: |
132 |
|
;;;; |
133 |
|
;;;; arithmetic: addition: integer |
134 |
|
;;;; arithmetic: addition: complex |
135 |
|
;;;; arithmetic: subtraction: integer |
136 |
|
;;;; arithmetic: subtraction: complex |
137 |
|
;;;; |
138 |
|
;;;; The Guile benchmarks use with-benchmark-prefix to include the name of |
139 |
|
;;;; the source file containing the benchmark in the benchmark name, to |
140 |
|
;;;; provide each file with its own namespace. |
141 |
|
|
142 |
|
|
143 |
|
;;;; ITERATION COUNTS |
144 |
|
;;;; |
145 |
|
;;;; Every benchmark has to be given an iteration count that indicates how |
146 |
|
;;;; often it should be executed. The reason is, that in most cases a single |
147 |
|
;;;; execution of the benchmark code would not deliver usable timing results: |
148 |
|
;;;; The resolution of the system time is not arbitrarily fine. Thus, some |
149 |
|
;;;; benchmarks would be executed too quickly to be measured at all. A rule |
150 |
|
;;;; of thumb is, that the longer a benchmark runs, be more exact is the |
151 |
|
;;;; information about the execution time. |
152 |
|
;;;; |
153 |
|
;;;; However, execution time depends on several influences: First, the |
154 |
|
;;;; machine you are running the benchmark on. Second, the compiler you use. |
155 |
|
;;;; Third, which compiler options you use. Fourth, which version of guile |
156 |
|
;;;; you are using. Fifth, which guile options you are using (for example if |
157 |
|
;;;; you are using the debugging evaluator or not). There are even more |
158 |
|
;;;; influences. |
159 |
|
;;;; |
160 |
|
;;;; For this reason, the same number of iterations for a single benchmark may |
161 |
|
;;;; lead to completely different execution times in different |
162 |
|
;;;; constellations. For someone working on a slow machine, the default |
163 |
|
;;;; execution counts may lead to an inacceptable execution time of the |
164 |
|
;;;; benchmark suite. For someone on a very fast machine, however, it may be |
165 |
|
;;;; desireable to increase the number of iterations in order to increase the |
166 |
|
;;;; accuracy of the time data. |
167 |
|
;;;; |
168 |
|
;;;; For this reason, the benchmark suite allows to scale the number of |
169 |
|
;;;; executions by a global factor, stored in the exported variable |
170 |
|
;;;; iteration-factor. The default for iteration-factor is 1. A number of 2 |
171 |
|
;;;; means, that all benchmarks are executed twice as often, which will also |
172 |
|
;;;; roughly double the execution time for the benchmark suite. Similarly, if |
173 |
|
;;;; iteration-factor holds a value of 0.5, only about half the execution time |
174 |
|
;;;; will be required. |
175 |
|
;;;; |
176 |
|
;;;; It is probably a good idea to choose the iteration count for each |
177 |
|
;;;; benchmark such that all benchmarks will take about the same time, for |
178 |
|
;;;; example one second. To achieve this, the benchmark suite holds an empty |
179 |
|
;;;; benchmark in the file 0-reference.bm named "reference benchmark for |
180 |
|
;;;; iteration counts". It's iteration count is calibrated to make the |
181 |
|
;;;; benchmark run about one second on Dirk's laptop :-) If you are adding |
182 |
|
;;;; benchmarks to the suite, it would be nice if you could calibrate the |
183 |
|
;;;; number of iterations such that each of your added benchmarks takes about |
184 |
|
;;;; as long to run as the reference benchmark. But: Don't be too accurate |
185 |
|
;;;; to figure out the correct iteration count. |
186 |
|
|
187 |
|
|
188 |
|
;;;; REPORTERS |
189 |
|
;;;; |
190 |
|
;;;; A reporter is a function which we apply to each benchmark outcome. |
191 |
|
;;;; Reporters can log results, print interesting results to the standard |
192 |
|
;;;; output, collect statistics, etc. |
193 |
|
;;;; |
194 |
|
;;;; A reporter function takes the following arguments: NAME ITERATIONS |
195 |
|
;;;; BEFORE AFTER GC-TIME. The argument NAME holds the name of the benchmark, |
196 |
|
;;;; ITERATIONS holds the actual number of iterations that were performed. |
197 |
|
;;;; BEFORE holds the result of the function (times) at the very beginning of |
198 |
|
;;;; the excution of the benchmark, AFTER holds the result of the function |
199 |
|
;;;; (times) after the execution of the benchmark. GC-TIME, finally, holds |
200 |
|
;;;; the difference of calls to (gc-run-time) before and after the execution |
201 |
|
;;;; of the benchmark. |
202 |
|
;;;; |
203 |
|
;;;; This library provides some standard reporters for logging results |
204 |
|
;;;; to a file, reporting interesting results to the user, (FIXME: and |
205 |
|
;;;; collecting totals). |
206 |
|
;;;; |
207 |
|
;;;; You can use the REGISTER-REPORTER function and friends to add whatever |
208 |
|
;;;; reporting functions you like. See under ;;;; TIMING DATA to see how the |
209 |
|
;;;; library helps you to extract relevant timing information from the values |
210 |
|
;;;; ITERATIONS, BEFORE, AFTER and GC-TIME. If you don't register any |
211 |
|
;;;; reporters, the library uses USER-REPORTER, which writes the most |
212 |
|
;;;; interesting results to the standard output. |
213 |
|
|
214 |
|
|
215 |
|
;;;; TIME CALCULATION |
216 |
|
;;;; |
217 |
|
;;;; The library uses the guile functions (times) and (gc-run-time) to |
218 |
|
;;;; determine the execution time for a single benchmark. Based on these |
219 |
|
;;;; functions, the values of BEFORE, AFTER and GC-TIME are computed, which |
220 |
|
;;;; are then passed to the reporter functions. All three values BEFORE, |
221 |
|
;;;; AFTER and GC-TIME include the time needed to executed the benchmark code |
222 |
|
;;;; itself, but also the surrounding code that implements the loop to run the |
223 |
|
;;;; benchmark code for the given number of times. This is undesirable, since |
224 |
|
;;;; one would prefer to only get the timing data for the benchmarking code. |
225 |
|
;;;; |
226 |
|
;;;; To cope with this, the benchmarking framework uses a trick: During |
227 |
|
;;;; initialization of the library, the time for executing an empty benchmark |
228 |
|
;;;; is measured and stored. This is an estimate for the time needed by the |
229 |
|
;;;; benchmarking framework itself. For later benchmarks, this time can then |
230 |
|
;;;; be subtracted from the measured execution times. |
231 |
|
;;;; |
232 |
|
;;;; In order to simplify the time calculation for users who want to write |
233 |
|
;;;; their own reporters, benchmarking framework provides the following |
234 |
|
;;;; definitions: |
235 |
|
;;;; |
236 |
|
;;;; benchmark-time-base : This variable holds the number of time units that |
237 |
|
;;;; make up a second. By deviding the results of each of the functions |
238 |
|
;;;; below by this value, you get the corresponding time in seconds. For |
239 |
|
;;;; example (/ (benchmark-total-time before after) benchmark-time-base) |
240 |
|
;;;; will give you the total time in seconds. |
241 |
|
;;;; benchmark-total-time : this function takes two arguments BEFORE and AFTER |
242 |
|
;;;; and computes the total time between the two timestamps. The result |
243 |
|
;;;; of this function is what the time command of the unix command line |
244 |
|
;;;; would report as real time. |
245 |
|
;;;; benchmark-user-time : this function takes two arguments BEFORE and AFTER |
246 |
|
;;;; and computes the time spent in the benchmarking process between the |
247 |
|
;;;; two timestamps. That means, the time consumed by other processes |
248 |
|
;;;; running on the same machine is not part of the resulting time, |
249 |
|
;;;; neither is time spent within the operating system. The result of |
250 |
|
;;;; this function is what the time command of the unix command line would |
251 |
|
;;;; report as user time. |
252 |
|
;;;; benchmark-system-time : similar to benchmark-user-time, but here the time |
253 |
|
;;;; spent within the operating system is given. The result of this |
254 |
|
;;;; function is what the time command of the unix command line would |
255 |
|
;;;; report as system time. |
256 |
|
;;;; benchmark-frame-time : this function takes the argument ITERATIONS. It |
257 |
|
;;;; reports the part of the user time that is consumed by the |
258 |
|
;;;; benchmarking framework itself to run some benchmark for the giben |
259 |
|
;;;; number of iterations. You can think of this as the time that would |
260 |
|
;;;; still be consumed, even if the benchmarking code itself was empty. |
261 |
|
;;;; This value does not include any time for garbage collection, even if |
262 |
|
;;;; it is the benchmarking framework which is responsible for causing a |
263 |
|
;;;; garbage collection. |
264 |
|
;;;; benchmark-core-time : this function takes three arguments ITERATIONS, |
265 |
|
;;;; BEFORE and AFTER. It reports the part of the user time that is |
266 |
|
;;;; actually spent within the benchmarking code. That is, the time |
267 |
|
;;;; needed for the benchmarking framework is subtracted from the user |
268 |
|
;;;; time. This value, however, includes all garbage collection times, |
269 |
|
;;;; even if some part of the gc-time had actually to be attributed to the |
270 |
|
;;;; benchmarking framework. |
271 |
|
;;;; benchmark-user-time\interpreter : this function takes three arguments |
272 |
|
;;;; BEFORE AFTER and GC-TIME. It reports the part of the user time that |
273 |
|
;;;; is spent in the interpreter (and not in garbage collection). |
274 |
|
;;;; benchmark-core-time\interpreter : this function takes four arguments |
275 |
|
;;;; ITERATIONS, BEFORE, AFTER. and GC-TIME. It reports the part of the |
276 |
|
;;;; benchmark-core-time that is spent in the interpreter (and not in |
277 |
|
;;;; garbage collection). This value is most probably the one you are |
278 |
|
;;;; interested in, except if you are doing some garbage collection |
279 |
|
;;;; checks. |
280 |
|
;;;; |
281 |
|
;;;; There is not function to calculate the garbage-collection time, since the |
282 |
|
;;;; garbage collection time is already passed as an argument GC-TIME to the |
283 |
|
;;;; reporter functions. |
284 |
|
|
285 |
|
|
286 |
;;;; MISCELLANEOUS |
;;;; MISCELLANEOUS |
287 |
;;;; |
;;;; |
288 |
|
|
368 |
;;;; TIME CALCULATION |
;;;; TIME CALCULATION |
369 |
;;;; |
;;;; |
370 |
|
|
371 |
(define time-base |
(define benchmark-time-base |
372 |
internal-time-units-per-second) |
internal-time-units-per-second) |
373 |
|
|
374 |
|
(define time-base ;; short-cut, not exported |
375 |
|
benchmark-time-base) |
376 |
|
|
377 |
(define frame-time/iteration |
(define frame-time/iteration |
378 |
"<will be set during initialization>") |
"<will be set during initialization>") |
379 |
|
|
380 |
(define (total-time before after) |
(define (benchmark-total-time before after) |
381 |
(- (tms:clock after) (tms:clock before))) |
(- (tms:clock after) (tms:clock before))) |
382 |
|
|
383 |
(define (user-time before after) |
(define (benchmark-user-time before after) |
384 |
(- (tms:utime after) (tms:utime before))) |
(- (tms:utime after) (tms:utime before))) |
385 |
|
|
386 |
(define (system-time before after) |
(define (benchmark-system-time before after) |
387 |
(- (tms:stime after) (tms:stime before))) |
(- (tms:stime after) (tms:stime before))) |
388 |
|
|
389 |
(define (frame-time iterations) |
(define (benchmark-frame-time iterations) |
390 |
(* iterations frame-time/iteration)) |
(* iterations frame-time/iteration)) |
391 |
|
|
392 |
(define (benchmark-time iterations before after) |
(define (benchmark-core-time iterations before after) |
393 |
(- (user-time before after) (frame-time iterations))) |
(- (benchmark-user-time before after) (benchmark-frame-time iterations))) |
394 |
|
|
395 |
(define (user-time\interpreter before after gc-time) |
(define (benchmark-user-time\interpreter before after gc-time) |
396 |
(- (user-time before after) gc-time)) |
(- (benchmark-user-time before after) gc-time)) |
397 |
|
|
398 |
(define (benchmark-time\interpreter iterations before after gc-time) |
(define (benchmark-core-time\interpreter iterations before after gc-time) |
399 |
(- (benchmark-time iterations before after) gc-time)) |
(- (benchmark-core-time iterations before after) gc-time)) |
400 |
|
|
401 |
|
|
402 |
;;;; REPORTERS |
;;;; REPORTERS |
442 |
;;; Display a single benchmark result to the given port |
;;; Display a single benchmark result to the given port |
443 |
(define (print-result port name iterations before after gc-time) |
(define (print-result port name iterations before after gc-time) |
444 |
(let* ((name (format-benchmark-name name)) |
(let* ((name (format-benchmark-name name)) |
445 |
(total-time (total-time before after)) |
(total-time (benchmark-total-time before after)) |
446 |
(user-time (user-time before after)) |
(user-time (benchmark-user-time before after)) |
447 |
(system-time (system-time before after)) |
(system-time (benchmark-system-time before after)) |
448 |
(frame-time (frame-time iterations)) |
(frame-time (benchmark-frame-time iterations)) |
449 |
(benchmark-time (benchmark-time iterations before after)) |
(benchmark-time (benchmark-core-time iterations before after)) |
450 |
(user-time\interpreter (user-time\interpreter before after gc-time)) |
(user-time\interpreter |
451 |
(benchmark-time\interpreter |
(benchmark-user-time\interpreter before after gc-time)) |
452 |
(benchmark-time\interpreter iterations before after gc-time))) |
(benchmark-core-time\interpreter |
453 |
|
(benchmark-core-time\interpreter iterations before after gc-time))) |
454 |
(write (list name iterations |
(write (list name iterations |
455 |
"total:" (/ total-time time-base) |
"total:" (/ total-time time-base) |
456 |
"user:" (/ user-time time-base) |
"user:" (/ user-time time-base) |
458 |
"frame:" (/ frame-time time-base) |
"frame:" (/ frame-time time-base) |
459 |
"benchmark:" (/ benchmark-time time-base) |
"benchmark:" (/ benchmark-time time-base) |
460 |
"user/interp:" (/ user-time\interpreter time-base) |
"user/interp:" (/ user-time\interpreter time-base) |
461 |
"bench/interp:" (/ benchmark-time\interpreter time-base) |
"bench/interp:" (/ benchmark-core-time\interpreter time-base) |
462 |
"gc:" (/ gc-time time-base)) |
"gc:" (/ gc-time time-base)) |
463 |
port) |
port) |
464 |
(newline port))) |
(newline port))) |
479 |
;;; Display interesting results of a single benchmark to the given port |
;;; Display interesting results of a single benchmark to the given port |
480 |
(define (print-user-result port name iterations before after gc-time) |
(define (print-user-result port name iterations before after gc-time) |
481 |
(let* ((name (format-benchmark-name name)) |
(let* ((name (format-benchmark-name name)) |
482 |
(user-time (user-time before after)) |
(user-time (benchmark-user-time before after)) |
483 |
(benchmark-time (benchmark-time iterations before after)) |
(benchmark-time (benchmark-core-time iterations before after)) |
484 |
(benchmark-time\interpreter |
(benchmark-core-time\interpreter |
485 |
(benchmark-time\interpreter iterations before after gc-time))) |
(benchmark-core-time\interpreter iterations before after gc-time))) |
486 |
(write (list name iterations |
(write (list name iterations |
487 |
"user:" (/ user-time time-base) |
"user:" (/ user-time time-base) |
488 |
"benchmark:" (/ benchmark-time time-base) |
"benchmark:" (/ benchmark-time time-base) |
489 |
"bench/interp:" (/ benchmark-time\interpreter time-base) |
"bench/interp:" (/ benchmark-core-time\interpreter time-base) |
490 |
"gc:" (/ gc-time time-base)) |
"gc:" (/ gc-time time-base)) |
491 |
port) |
port) |
492 |
(newline port))) |
(newline port))) |
505 |
(benchmark "empty initialization benchmark" 2 #t) |
(benchmark "empty initialization benchmark" 2 #t) |
506 |
|
|
507 |
;;; Second, initialize the system constants |
;;; Second, initialize the system constants |
508 |
|
(display ";; calibrating the benchmarking framework..." (current-output-port)) |
509 |
|
(newline (current-output-port)) |
510 |
(define (initialization-reporter name iterations before after gc-time) |
(define (initialization-reporter name iterations before after gc-time) |
511 |
(let* ((frame-time (- (tms:utime after) (tms:utime before) gc-time 3))) |
(let* ((frame-time (- (tms:utime after) (tms:utime before) gc-time 3))) |
512 |
(set! frame-time/iteration (/ frame-time iterations)) |
(set! frame-time/iteration (/ frame-time iterations)) |
513 |
(display ";; frame time per iteration: " (current-output-port)) |
(display ";; framework time per iteration: " (current-output-port)) |
514 |
(display (/ frame-time/iteration time-base) (current-output-port)) |
(display (/ frame-time/iteration time-base) (current-output-port)) |
515 |
(newline (current-output-port)))) |
(newline (current-output-port)))) |
516 |
(set! default-reporter initialization-reporter) |
(set! default-reporter initialization-reporter) |
518 |
|
|
519 |
;;; Finally, set the default reporter |
;;; Finally, set the default reporter |
520 |
(set! default-reporter user-reporter) |
(set! default-reporter user-reporter) |
521 |
|
|