ホーム » スタッフ » 斉藤徹 » 講義録 » 情報構造論 » プログラムの処理時間の測り方

2021年12月
 1234
567891011
12131415161718
19202122232425
262728293031  

検索・リンク

プログラムの処理時間の測り方

今回の課題レポートでは、テスト素点が良くレポート提出でも加点が少ないと思われる人でも、まじめに取り組んだレポート提出が多かった。この中で、興味深いレポートで、2分探索木の検索が偏っていたらO(N),バランスが良ければO(log N)の検証をしているものがあった。ただ、計測方法がちょっと残念だったので解説。

処理時間の計測方法

速度の検証をするにしてもデータ数も少なく、検索は一瞬で終わってしまうので、以下のような 1000 回ループで時間を測定していた。1000回といったループで計測するのは正しいアプローチ。

for( int i = 0 ; i < 1000 ; i++ ) {
   if ( find( top , key ) )
      printf( "みつかった" ) ;
   else
      printf( "みつからない" ) ;
}

ただ、この方法では、find() の処理時間以上に、printf() の処理時間の方が問題となる。

printf の処理時間

printf は、ただでさえも、第一引数の中にある “%” フォーマットの分析をするという面倒な処理をしているので、かなり複雑な処理をしている関数。メモリ容量の少ない組込み系のシステムを構築する時は、%フォーマットの分析のコードも大きくなるので、使うのを避けることも多い。

また、printf は、%フォーマットの解析に加え、出力バッファリングなどを経て、最終的に文字を標準出力に出力する。標準出力への出力が発生すると、OSのシステムコールを呼び出し、結果を表示するターミナルプログラムは、画面への文字の出力や、画面からはみ出た文字のスクロールアップなどの処理を行う。このため、find() 関数の処理時間以上に手間がかかっている。このため、精度の低い結果となってしまっている。

つまり、自分の関数の処理時間を計測したいなら、余計な時間がかかる printf などの入出力処理は時間計測に含めないこと。

time コマンド

プログラムの処理時間を測る場合には、測定対象のプログラムの処理時間の他にも、最近のOSではマルチタスクだからこそ、他の並列処理にとられている時間、OSでマルチタスクの切替に係る時間なども含まれてしまう。

このため Linux 環境でプロセスの処理時間を測定する場合には、time コマンドを用いる。

((( ちょっと時間のかかりそうな /usr/lib 配下のファイルの一覧出力 )))
$ find /usr/lib -type f -print
(略)
((( time コマンドは、time の後ろに計測したい処理を書く )))
$ time find /usr/lib -type f -print 
(略)
0.00s user 0.33s system 26% cpu 1.242 total
((( 比較のために出力を /dev/null に捨てて実行 )))
$ time find /usr/lib -type f -print > /dev/null
find /usr/lib -type f -print > /dev/null
0.00s user 0.25s system 87% cpu 0.287 total

この例では、find 自体の処理時間 user 時間 0秒、find が 出力命令のようなシステムコールを実行したことによる OS の処理時間 system 時間 0.33 秒、出力なども含めて見かけ上の本当の処理時間が 1.242 秒というのがわかる。

この結果を見ても、如何に出力処理が遅いのかが分かる。

だからこそ、自分のプログラムの処理時間として使う場合は、user 時間の部分を使うこと。

プロファイラによる解析

プログラムの処理が遅い場合の原因を究明する場合には、プロファイラというプログラムを用いることが多い。

例えば gcc などのコンパイラのためのプロファイラの gprof では、プログラムの処理に一定時間で割り込みをかけ、そのタイミング毎にどの関数の処理中だったのかを調べることで、全体の処理時間の何パーセントをその関数の処理をしていた…ということを計測できる。(統計的プロファイラ)

((( 測定対象のプログラムにプロファイラ用の情報を埋め込んでコンパイル )))
$ gcc -pg foobar.c
((( プログラムを実行すると gmon.out という統計情報が出力される )))
$ ./a.out
((( gprof で統計結果の確認 )))
$ gprof ./a.out gmon.out

といっても、割り込みをかけて計測しているので、プロファイラの結果は精度の高いデータとは言えない。