時間計測に関わる変数
internal-time-units-per-second
-
これは，各手続きが使用している時間単位の1秒当たりの回数（exactな整数値）に束縛された大域変数です．
以下の実行例が示すように，その値は $10^9$ です．
従って，
各手続きはナノ秒単位で時間を計測していることになります．
$ guile GNU Guile 3.0.5 ..... 起動メッセージ ...... guile> internal-time-units-per-second $1 = 1000000000 guile>
時間計測のための手続き（１）
(times)
-
この手続きは，
この手続きを呼び出したプロセスに関する実時間やCPU時間を格納したベクタを返します．
guile> (times) $2 = #(17313891580000000 50000000 10000000 0 0) guile>上記のベクタは， REPLを動かしているプロセスに関する各種時間を格納しています． ベクタの各成分の意味は下記の手続きの説明を参照して下さい． 以下，このベクタを便宜的に時間ベクタと呼ぶことにします． Guile 3.0.7のソースコード（stime.c）を見ると， この手続きはglibcのtimes関数を使って実装されています． 筆者の環境では，times関数は10ミリ秒単位で時間を計測しています（詳細は後述）． そのため，この手続きは10ミリ秒単位で計測した時間をナノ秒に変換して（つまり，$10^7$倍して）返しています． これはGuileの時間単位（internal-time-units-per-secondが示す時間単位）に合わせるためです．上記の返り値を見ると10ミリ秒単位で計測していること（つまり， 実際の計測値を$10^7$倍していること）が分かります．
(tms:clock tms)
-
この手続きは，時間ベクタ
tms
の第0成分を返します．その第0成分は，
適当な基準時刻からの経過時間（実時間）です．
guile> (tms:clock $2) $3 = 17313891580000000 guile>上記の実行例は， 上で実行した times 手続きの返り値（$2）を利用しています． 従って，この結果（$3）は， REPLを動かしているプロセスの経過時間です． なお，「適応な基準時刻」についてはtimes関数のオンラインマニュアルを参照して下さい．
(tms:utime tms)
-
この手続きは，時間ベクタ
tms
の第1成分を返します．POSIXの仕様書によれば，その第1成分は次の通りです．
the CPU time charged for the execution of user instructions of the calling process
いわゆるユーザーCPU時間です．guile> (tms:utime $2) $4 = 50000000 guile>上記の実行例は， 上で実行した times 手続きの返り値（$2）を利用しています． 従って，この結果（$4）は， REPLを動かしているプロセスのユーザーCPU時間です．
(tms:stime tms)
-
この手続きは，時間ベクタ
tms
の第2成分を返します．POSIXの仕様書によれば，その第2成分は次の通りです．
the CPU time charged for execution by the system on behalf of the calling process
いわゆるシステムCPU時間です．guile> (tms:stime $2) $5 = 10000000 guile>この結果（$5）は， REPLを動かしているプロセスのシステムCPU時間です．
(tms:cutime tms)
-
この手続きは，時間ベクタ
tms
の第3成分を返します．POSIXの仕様書によれば，その第3成分は次の通りです．
the sum of the tms utime and tms cutime times of the child processes
これは，現行プロセスの子や孫のプロセスのユーザーCPU時間の総和です． 現行プロセスのユーザーCPU時間は含みません． なお，cutimeを再帰的に定義していることに注意して下さい．guile> (tms:cutime $2) $6 = 0 guile>この結果（$6）は， REPLを動かしているプロセスの子や孫のプロセスのユーザーCPU時間の総和です． 子や孫のプロセスを生成していないので，その値は0（ナノ秒）になっています．
(tms:cstime tms)
-
この手続きは，時間ベクタ
tms
の第4成分を返します．POSIXの仕様書によれば，その第4成分は次の通りです．
the sum of the tms stime and tms cstime times of the child processes
これは，現行プロセスの子や孫のプロセスのシステムCPU時間の総和です． 現行プロセスのシステムCPU時間は含みません． なお，cstimeを再帰的に定義していることに注意して下さい．guile> (tms:cstime $2) $7 = 0 guile>この結果（$7）は， REPLを動かしているプロセスの子や孫のプロセスのシステムCPU時間の総和です． 子や孫のプロセスを生成していないので，その値は0（ナノ秒）になっています．
補足
- 上記のベクタの第0成分は，times関数の返り値（経過時間）で，第1成分〜第4成分はtms構造体の各メンバの値です．
-
現行プロセスのCPU時間（tms:utimeやtms:stime）は，
子や孫のプロセスのCPU時間を含みません．
この点を確かめてみます．
$ guile ... 起動メッセージ ...... guile> (system "guile -c '(let loop ((n 20000000)) (when (> n 0) (loop (1- n))))'") $1 = 0 guile> (times) $2 = #(17207182320000000 50000000 10000000 2390000000 30000000) guile> (tms:utime $2) $3 = 50000000 guile> (tms:stime $2) $4 = 10000000 guile> (tms:cutime $2) $5 = 2390000000 guile> (tms:cstime $2) $6 = 30000000 guile>
この実行例は，system 手続きを使って子プロセスを生成し， その子プロセスの上で次のコマンドを実行しています．guile -c '(let loop ((n 20000000)) (when (> n 0) (loop (1- n))))'これは，let以降のループプログラムをguileコマンドに実行させています． 上記の実行結果を見ると， 現行プロセス（REPLを動かしているプロセス）のCPU時間（utimeとstime）が， 子プロセスのCPU時間（cutimeとcstime）を含んでいないことが分かります． -
POSIXの仕様書
や
オンラインマニュアル
によれば，times 関数が求める各種時間 は clock tick の回数を表しているそうです．clock tick とは，カーネルによるタイマー割り込みのことだそうです．
参考のために，
POSIXの定義を掲載します．
An interval of time; an implementation-defined number of these occur each second. Clock ticks are one of the units that may be used to express a value found in type clock_t.
オンラインマニュアルによれば，1秒当たりの clock tick の回数はsysconf(_SC_CLK_TCK)によって求めることができるそうです． そこで，以下のプログラムを使って， 筆者の環境（Debian 11）でこの回数を求めてみました．#include <stdio.h> #include <unistd.h> #include <time.h> // clock-tick.c int main(void){ printf("_SC_CLK_TCK = %ld\n", sysconf(_SC_CLK_TCK)); return 0; }$ gcc clock-tick.c $ ./a.out _SC_CLK_TCK = 100
この結果から，1秒当たりの clock tick の回数は100回です． これより，times 関数は各種時間を10ミリ秒単位で求めていることになります． Guile側の times 手続きは，その時間をナノ秒単位に変換して（つまり，$10^7$倍して）返しています．これは，Guileの時間単位（internal-time-units-per-secondが示す時間単位）に合わせるためです．
時間計測のための手続き（２）
(get-internal-real-time)
-
REPL または Guile スクリプトが実行を開始した時刻からの経過時間（実時間）を，internal-time-units-per-second が示す時間単位（筆者の環境ではナノ秒単位）に変換して返します．
$ guile GNU Guile 3.0.5 ...... 起動メッセージ ...... guile> (get-internal-real-time) $1 = 11645165765 guile>
Guile 3.0.7のソースコード（stime.c）を見ると，REPLまたはスクリプトの開始時刻と get-internal-real-time 手続きを実行したときの時刻を glibc の clock_gettime 関数を使って次のように求めていて， それらの時刻から経過時間を求めて返しています．clock_gettime (CLOCK_REALTIME, &ts);CLOCK_REALTIME は経過時間を計測することを指示するglibcのマクロです．&ts は timespec 構造体へのポインタです．これらの詳細は オンラインマニュアル か POSIXの仕様書 を参照して下さい．
(get-internal-run-time)
-
REPLまたはGuileスクリプトが実行を開始した時刻からのCPU 時間（ユーザとシステムの両方を含む）を，internal-time-units-per-second が示す時間単位（筆者の環境ではナノ秒単位）に変換して返します．ただし，子プロセスのCPU時間は含みません．
guile> (system "guile -c '(let loop ((n 20000000)) (when (> n 0) (loop (1- n))))'") $2 = 0 guile> (get-internal-run-time) $3 = 155646450 guile> (tms:cutime (times)) $4 = 2440000000 guile>
この実行例では，子プロセスを生成して， 子プロセスのCPU時間が親プロセス（REPLのプロセス）のCPU時間に含まれていないことを確認しています． Guile 3.0.7のソースコード（stime.c）を見ると，REPLまたはスクリプトの開始時刻と get-internal-run-time 手続きを実行したときの時刻を glibc の clock_gettime 関数を使って次のように求めていて， それらの時刻から経過時間を求めて返しています．clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &ts);CLOCK_PROCESS_CPUTIME_ID はCPU時間を計測することを指示するglibcのマクロです．&ts は timespec 構造体へのポインタです．これらの詳細は オンラインマニュアル か POSIXの仕様書 を参照して下さい．
プログラム例
ユーティリティ
-
まず，時間計測のためのユーティリティを作成します．
なお，時間計測は
get-internal-real-time
と
get-internal-run-time
を利用します．
;; time-utils.scm (define-module (time-utils) #:export ( internal-time-unit->second internal-time-unit->milisecond measure-real-time measure-real-time-second measure-real-time-milisecond measure-run-time measure-run-time-second measure-run-time-milisecond ) );; 内部時間単位を秒単位に変換する． (define (internal-time-unit->second t) (exact->inexact (/ t internal-time-units-per-second))) ;; 内部時間単位をミリ秒単位に変換する． (define (internal-time-unit->milisecond t) (exact->inexact (* (/ t internal-time-units-per-second) 1000)))
;; サンク thunk の実時間を返す． (define (measure-real-time thunk) (define start-time #f) (define end-time #f) (set! start-time (get-internal-real-time)) (thunk) (set! end-time (get-internal-real-time)) (- end-time start-time)) (define (measure-real-time-second thunk) (internal-time-unit->second (measure-real-time thunk))) (define (measure-real-time-milisecond thunk) (internal-time-unit->milisecond (measure-real-time thunk)))
;; サンク thunk のCPU時間を返す． (define (measure-run-time thunk) (define start-time #f) (define end-time #f) (set! start-time (get-internal-run-time)) (thunk) (set! end-time (get-internal-run-time)) (- end-time start-time)) (define (measure-run-time-second thunk) (internal-time-unit->second (measure-run-time thunk))) (define (measure-run-time-milisecond thunk) (internal-time-unit->milisecond (measure-run-time thunk)))
;; サンク thunk の実時間とCPU時間を返す． (define (measure-time thunk) (define start-real-time #f) (define end-real-time #f) (define start-run-time #f) (define end-run-time #f) (set! start-real-time (get-internal-real-time)) (set! start-run-time (get-internal-run-time)) (thunk) (set! end-run-time (get-internal-run-time)) (set! end-real-time (get-internal-real-time)) (vector (- end-real-time start-real-time) (- end-run-time start-run-time))) (define (measure-time-second thunk) (let ((tm (measure-time thunk))) (vector (internal-time-unit->second (vector-ref tm 0)) (internal-time-unit->second (vector-ref tm 1))))) (define (measure-time-milisecond thunk) (let ((tm (measure-time thunk))) (vector (internal-time-unit->milisecond (vector-ref tm 0)) (internal-time-unit->milisecond (vector-ref tm 1)))))
具体例（CPU時間だけを計測）
-
下記のプログラムを使って，
フィボナッチ数を再帰的に求めるときのCPU時間を計測してみることにします．
#!/usr/bin/guile \ -e main -s !# ;; fib.scm (add-to-load-path (getcwd)) (use-modules (time-utils)) (define (main args) (let loop ((n 31)) (when (<= n 40) (let ((tm (measure-run-time-second (lambda () (fib n))))) (format (current-output-port) "fib(~A) run time: ~Asec\n" n (measure-run-time-second (lambda () (fib n))))) (loop (1+ n))))) (define (fib n) (if (<= n 1) n (+ (fib (- n 1)) (fib (- n 2)))))$ ./fib.scm fib(31) run time: 0.036721221sec fib(32) run time: 0.059259689sec fib(33) run time: 0.095719044sec fib(34) run time: 0.155226124sec fib(35) run time: 0.251870521sec fib(36) run time: 0.4119074sec fib(37) run time: 0.657884752sec fib(38) run time: 1.066331158sec fib(39) run time: 1.73796392sec fib(40) run time: 2.789079806sec
具体例（実時間とCPU時間を同時に計測）
-
今度は，実時間とCPU時間の両方を同時に計測してみることにします．
前に示した measure-time 手続きは，
実時間を計測する際に
get-internal-run-time
手続き（2回分）の時間も含めています．
その時間はとても小さく，
実時間の計測に際してほとんど無視できると期待されます．
でも，気になるので，
下記のプログラムでは，get-internal-run-time（2回分）の実時間を計測しています．
さらに，実時間とCPU時間の差異を明確にするために，
計測対象のサンクに
(sleep 1) （1秒間休止する）
を追加しています．これによって，実時間がCPU時間よりも約1秒長くなるはずです．#!/usr/bin/guile \ -e main -s !# ;; fib-time.scm (add-to-load-path (getcwd)) (use-modules (time-utils)) (define (main args) ;; get-internal-run-time（2回分）の実時間を計測する． (let ((start #f) (end #f)) (set! start (get-internal-real-time)) (get-internal-run-time) (get-internal-run-time) (set! end (get-internal-real-time)) (format (current-output-port) "The charge of get-internal-run-tim: ~Asec\n" (internal-time-unit->second (- end start)))) ;; フィボナッチ数を計算する際の実時間とCPU時間を計測する． (let loop ((n 31)) (when (<= n 40) (let ((tm (measure-time-second (lambda () (sleep 1) (fib n))))) (format (current-output-port) "fib(~A) real time: ~Asec run time: ~Asec\n" n (vector-ref tm 0) (vector-ref tm 1))) (loop (1+ n))))) (define (fib n) (if (<= n 1) n (+ (fib (- n 1)) (fib (- n 2)))))$ ./fib-time.scm The charge of get-internal-run-tim: 4.776e-6sec fib(31) real time: 1.086667835sec run time: 0.081440635sec fib(32) real time: 1.114826173sec run time: 0.108369419sec fib(33) real time: 1.163550528sec run time: 0.156801333sec fib(34) real time: 1.24215678sec run time: 0.232377753sec fib(35) real time: 1.363600118sec run time: 0.350791737sec fib(36) real time: 1.565089412sec run time: 0.54537997sec fib(37) real time: 1.89996989sec run time: 0.874181012sec fib(38) real time: 2.435494681sec run time: 1.395762839sec fib(39) real time: 2.902076039sec run time: 1.900760767sec fib(40) real time: 4.070046108sec run time: 3.067266115sec実行結果を見ると， get-internal-run-time（2回分）の実時間は $4.776 \times 10^{-6}$ 秒なので（注：何回計測しても同じような値です）， ミリ秒単位で実時間を計測する限りそのその影響は無視できると言えます． また，(sleep 1) によって， 期待通りに実時間がCPU時間よりも約1秒長くなっています．
(おしまい)