For Gauche 0.9.5


Next: , Previous: , Up: ライブラリモジュール - Gauche拡張モジュール   [Contents][Index]

9.33 gauche.time - 時間の計測

Module: gauche.time

Schemeコードの実行時間を測る3つの方法を提供します。 インタラクティブな使用に便利なtimeマクロ、 ベンチマークのための手続きのセット、 プログラム中に埋め込んで使える<time-counter>オブジェクトです。

インタラクティブな実行時間の計測

註: timeマクロはgauche.timeモジュールをオートロードする ようにあらかじめ定義されているので、timeマクロを使うだけなら (use gauche.time)としておく必要はありません。

Macro: time expr expr2 …

expr expr2 … を順に評価し、最後の式の結果を返します。 結果が返される前に、全ての式の評価にかかった実(経過)時間および ユーザースペース、カーネルスペースで費されたCPU時間がカレントエラーポートに 報告されます。

現在の実装は、経過時間に対してはsys-gettimeofday (時間参照)を、CPU時間に対してはsys-times (システムへの問い合わせ参照)を用いています。従って、 それぞれの数値の分解能はこれらの手続きが用いているシステムコールに依存します。 CPU時間は10ms単位で、経過時間はそれより細かいことが多いです。 但しgettimeofday(2)コールをサポートしていないOSでは経過時間が最悪の場合 秒単位になります。

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

ベンチマーク

計測したいルーチンの一回の実行が一瞬で終わるために、 何度も繰り返して実行してより正確に時間を測りたいということはよくあります。 また、複数の実装を計測して比べてみたいということもよくあります。 ここに挙げるのは、そのために便利な手続きです。

これらベンチマーク手続きの名前と振る舞いは、PerlのBenchmarkモジュールを 参考にしています。

Function: time-this how thunk

thunkを何度も呼び出し、実行時間を測ります。 howには次の形が指定できます。

integer

指定された回数だけ、thunkを呼びます。

(cpu real)

CPU時間の合計が指定された数値(秒)を越えるまでthunkを繰り返し呼びます。

このルーチンはまた、thunkを実行するのと同じ回数だけ 空のループを実行して、その時間を結果から引くので、 結果にはthunkの実行時間のみが反映されます。

戻り値は後述する<time-result>レコードです。先に例を示しておきます。

;; 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>

ベンチマーク結果を保持するレコードです。以下のスロットがあります。

Instance Variable of <time-result>: count

thunkが実行された回数です。 このスロットはアクセサ手続きtime-result-countでもアクセスできます。

Instance Variable of <time-result>: real

thunkの実行にかかった実経過時間の合計です。 このスロットはアクセサ手続きtime-result-realでもアクセスできます。

Instance Variable of <time-result>: user

thunkの実行にかかったユーザCPU時間の合計です。 このスロットはアクセサ手続きtime-result-userでもアクセスできます。

Instance Variable of <time-result>: sys

thunkの実行にかかったシステムCPU時間の合計です。 このスロットはアクセサ手続きtime-result-sysでもアクセスできます。

Function: make-time-result count real user sys

<time-result>レコードのコンストラクタです。

Function: time-result? obj

<time-result>レコードかどうかを判定します。

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

ふたつの<time-result>レコードの和と差を求め、新しいレコードを返します。

with-countが偽なら、 real, user, sysの各スロットのみが計算対象となり、 結果のcountスロットはt1のcountスロットの値がそのまま引き継がれます。 これは、部分ごとに別々に計測された結果を対象に計算する場合を意図しています。

with-countが真なら、 countスロットも同様に計算対象となります。 これは、何度か走らせたベンチマーク結果を対象に計算する場合を意図しています。

Function: time-these how alist
Function: time-these/report how alist

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.

Function: report-time-results result

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:

(define (time-these/report how samples)
  (report-time-results (time-these how samples)))

より細かい計測

Class: <time-counter>

時間カウンタの抽象クラスです。時間カウンタは 時間の経過と共にその値が増加してゆく一種のタイマーです。 何度でもカウントを止めたり開始したりできます。 カウンタの値はカウントが止まっている時に読み出すことができます。 複数の時間カウンタを使えば、 例えばループ中の二つの部分について費される時間を別々に計測することもできます。

具体的なサブクラスが、どの時間をカウントするかを決定します。 時間カウンタを使うには、下に挙げるサブクラスのいずれかを インスタンシエイトしなければなりません。

Class: <real-time-counter>
Class: <user-time-counter>
Class: <system-time-counter>
Class: <process-time-counter>

それぞれ、実経過時間、ユーザースペースCPU時間、カーネルスペースCPU時間、 総CPU時間 (ユーザー+カーネル)を計測する時間カウンタのクラスです。

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

時間カウンタcounterを開始/停止します。カウンタが走っている間の時間が、 カウンタが停止した時点でカウンタの値に加算されます。

開始/停止の対はネストすることができます。その場合は、一番外側の対のみが 有効です。 つまり、既に走っているカウンタに対しtime-counter-start!を呼んでも 何も起こりませんが、一度余分にtime-counter-stop!を呼ばないと カウンタは止まりません。 これは、内部に既に開始/停止の対を含んでいるかもしれない大きなコードブロックの 全体の時間を計測したいというような場合に便利です。

既に停止しているカウンタに対してtime-counter-stop!を呼んでも 何も起こりません。

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

カウンタcounterの値をリセットします。既にcounterが走っている 場合は、リセットの前にカウンタは停止させられます。

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

カウンタcounterの現在の値(秒数)を実数で返します。 分解能はそれぞれのカウンタが用いているシステムコールに依存します。

Macro: with-time-counter counter expr …

expr …が評価される間だけcounterを走らせる、 便利なマクロです。最後の式の結果を返します。このマクロは次のように 定義されます。

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

下の例では、ループ内でのprocess-Aとprocess-Bにて費された 概略の時間をそれぞれ計測します。

(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))
  )

Next: , Previous: , Up: ライブラリモジュール - Gauche拡張モジュール   [Contents][Index]