9.36 gauche.time - Measure timings

Module: gauche.time ¶

Provides three ways to measure execution time of Scheme code. A macro time, which is convenient for interactive use, a set of procedures for benchmarking, and <time-counter> objects which are useful to be embedded in the program.

Interactive measurement of execution time

Note: The time macro is pre-defined to autoload gauche.time for the convenience; you don’t need to say (use gauche.time) to use the time macro.

Macro: time expr expr2 … ¶

{gauche.time} Evaluates expr expr2 … sequentially, as begin, and returns the result(s) of the last expression. Before returning the value(s), the macro reports the elapsed (real) time and CPU times in the user space and the kernel space to the current error port, much like the bourne shell’s time command.

The current version uses sys-gettimeofday (see Time) to calculate the elapsed time, and sys-times (see System inquiry) to calculate user and system CPU times. So the resolution of these numbers depends on these underlying system calls. Usually the CPU time has 10ms resolution, while the elapsed time might have higher resolution. On the systems that doesn’t have gettimeofday(2) support, however, the elapsed time resolution can be as bad as a second.

gosh> (time (length (sort (call-with-input-file "/usr/share/dict/words"
                                                port->string-list))))
;(time (length (sort (call-with-input-file "/usr/share/dict/words" port- ...
; real   0.357
; user   0.350
; sys    0.000
45427

Benchmarking

It is not unusual that the routine you want to measure takes only a fraction of second, so you have to run it many times for better measurement. It is also common that you want to compare results of measurement of two or more implementation strategies. Here are useful procedures to do so.

The name and behavior of those benchmarking routines are inspired by Perl’s Benchmark module.

Function: time-this how thunk ¶

{gauche.time} Calls thunk many times and measure its execution time. The argument how can be one of the following forms.

integer

It calls thunk as many times as the given number.

(metric real)

It calls thunk as many times as the total time exceeds the given number of seconds. Metric is either one of symbols cpu, user, sys, or real, to specify how the time is measured.

It also runs an empty loop as the same times and subtract the time took for the empty loop from the measured time, to get more accurate result.

The result is returned in a <time-result> record, described below. Here are some examples:

;; Run the thunk 1,000,000 times
(time-this 1000000 (lambda () (expt 100 30)))
  ⇒ #<time-result 1000000 times/  1.030 real/  1.040 user/  0.000 sys>

;; Run the thunk at least 5.0 cpu seconds
(time-this '(cpu 5.0) (lambda () (expt 100 30)))
  ⇒ #<time-result 4903854 times/  5.090 real/  5.050 user/  0.010 sys>

Record: <time-result> ¶

{gauche.time} A record to hold the benchmark result. Following slots are defined.

Instance Variable of <time-result>: count ¶

The number of times the thunk was run. This slot is also accessed by a procedure time-result-count.

Instance Variable of <time-result>: real ¶

The total real (elapsed) time running the thunk took. This slot is also accessed by a procedure time-result-real.

Instance Variable of <time-result>: user ¶

The total user cpu time running the thunk took. This slot is also accessed by a procedure time-result-user.

Instance Variable of <time-result>: sys ¶

The total system cpu time running the thunk took. This slot is also accessed by a procedure time-result-sys.

Function: make-time-result count real user sys ¶

{gauche.time} The constructor of <time-result> records.

Function: time-result? obj ¶

{gauche.time} The predicate of <time-result> records.

Function: time-result+ t1 t2 :key (with-count #f) ¶

Function: time-result- t1 t2 :key (with-count #f) ¶

{gauche.time} Add or subtract two <time-result> records and returns a new record.

If with-count is false, only the real, user and sys slots are added or subtracted, and the result’s count slot is set to the same as t1’s count slot. It is supposed to be used to calculate on measurement from different chunk of code.

If with-count is true, then the values of count slot is also added or subtracted. It is supposed to calculate on multiple benchmark results of the same code.

Function: time-these how alist ¶

Function: time-these/report how alist :key metric ¶

{gauche.time} These procedures benchmarks multiple chunks of code to compare.

The alist argument must be the form of ((key . thunk) …), where key is a symbol and thunk is a procedure taking no arguments.

The how argument is the same as time-this; that is, either an integer for number of iterations, or a list (cpu x) to indicate x seconds of cpu time.

time-these runs benchmarks for each thunk in alist using time-this, and returns the result in a list of the form (how (key1 . result1) (key2 . result2) …), where each result is a <time-result> object.

time-these/report outputs the benchmark results and comparison matrix in human readable way to the current output port.

gosh> (time-these/report '(cpu 3.0)
        `((real1 . ,(cut expt 100 20))
          (real2 . ,(cut %expt 100 20))
          (imag  . ,(cut expt +100i 20))))
Benchmark: ran real1, real2, imag, each for at least 3.0 cpu seconds.
  real1: 3.312 real, 3.320 cpu (3.320 user + 0.000 sys)@ 1694277.11/s n=5625000
  real2: 2.996 real, 3.010 cpu (3.010 user + 0.000 sys)@35595634.55/s n=107142860
   imag: 3.213 real, 3.190 cpu (3.190 user + 0.000 sys)@  862068.97/s n=2750000

              Rate  real1 real2   imag
  real1  1694277/s     -- 0.048  1.965
  real2 35595635/s 21.009    -- 41.291
   imag   862069/s  0.509 0.024     --

The first part of the report shows, for each thunks, the real (elapsed) time, the cpu time used (and its breakdown of user and system time), the rate of iteration per second, and the total number of iterations.

The second part compares the speed between each pair of the benchmarks. For example, its first row tells that the benchmark real1 is 0.048 times faster than real2 and 1.965 times faster than imag.

The metric argument specifies which time metric should be used for rate calculation and comparison. It must be either #f or one of the symbols cpu, user, sys, or real. If it is #f (default), the same metric as how argument is used (if how is an integer count, cpu is assumed).

Function: report-time-results result :optional metric ¶

{gauche.time} This is a utility procedure to create a report from the result of time-these. Actually, time-these/report is just a combination of time-these and this procedure:

The meaning of the optional metric argument is the same as the metric keyword argument of time-these/report.

(define (time-these/report how samples :key metric)
  (report-time-results (time-these how samples) metric))

Finer measurement

Class: <time-counter> ¶

{gauche.time} An abstract class of time counters. Time counter is a kind of timer whose value is incremented as the time passes. The counting can be started and stopped any number of times. The value of the counter can be read when the timer is stopping. You can have multiple time counters. It is useful, for example, to measure the time in two parts inside a loop independently.

The concrete subclass determines which time it is counting. You have to instantiate one of those subclasses described below to use the time counter.

Class: <real-time-counter> ¶

Class: <user-time-counter> ¶

Class: <system-time-counter> ¶

Class: <process-time-counter> ¶

{gauche.time} Classes for time counters that count real (elapsed) time, user-space CPU time, kernel-space CPU time, and total CPU time (user + system), respectively.

Method: time-counter-start! (counter <time-counter>) ¶

Method: time-counter-stop! (counter <time-counter>) ¶

{gauche.time} Starts and stops the counter. The time during the counter is running is accumulated to the counter value when the counter is stopped.

Start/stop pairs can be nested, but only the outermost pair takes the effect. That is, if you call time-counter-start! on the counter that is already started, it doesn’t have any effect except that to stop such a counter you have to call time-counter-stop! one more time. It is useful when you want to measure the time spent in the larger block that may already contain timer start/stop pairs.

Calling time-counter-stop! on the already stopped counter has no effect.

Method: time-counter-reset! (counter <time-counter>) ¶

{gauche.time} Resets the value of counter. If counter is already running, it is forced to stop before being reset.

Method: time-counter-value (counter <time-counter>) ¶

{gauche.time} Returns the current value of the counter as the number of seconds, in a real number. The resolution depends on the source of the counter.

Macro: with-time-counter counter expr … ¶

{gauche.time} A convenience macro to run the counter while expr … are evaluated. Returns the result(s) of the last expression. It is defined as follows.

(define-syntax with-time-counter
  (syntax-rules ()
    ((_ counter . exprs)
     (dynamic-wind
      (lambda () (time-counter-start! counter))
      (lambda () . exprs)
      (lambda () (time-counter-stop! counter))))
    ))

The following example measures approximate times spend in process-A and process-B inside a loop.

(let ((ta (make <real-time-counter>))
      (tb (make <real-time-counter>)))
  (dotimes (i 100000)
    (with-time-counter ta
      (process-A))
    (with-time-counter tb
      (process-B)))
  (format #t "Time spent in process-A: ~s\n" (time-counter-value ta))
  (format #t "Time spent in process-B: ~s\n" (time-counter-value tb))
  )