f

2016-12-08

How to time a program in POSIX shell script

この記事はPOSIX原理主義Advent Calendarの8日目だ。

POSIXに準拠した,プログラムの実行時間の計測方法を紹介する。

結論としては,timeコマンドを使って以下のようにサブシェルで実行するのが最善と判断した。

\time -p sh -c 'sleep 1'

Introduction

シェルスクリプトは複数のコマンドや構文の組み合わせにより構成される。そのため,ある処理を行う場合に複数の実現方法が存在することがよくある。例えば,変数VARと文字列TARGETが一致するかの判定には,以下の3通りの方法がある。

[ "$VAR" = "TARGET" ]                   && echo MATCH
printf '%s' "$VAR" | grep -q '^TARGET$' && echo MATCH
case "$VAR" in 'TARGET') echo MATCH;; esac

複数の実現方法が存在する場合は,以下の要素を考慮してどれが最善の方法かを検討して選ぶだろう。

コード選択時の判断材料
可読性
人が見て理解しやすい
記述量
記述量が少ない
実行速度
実行速度が速いか

これらの内,[可読性]と[記述量]はコードとして書かれた時点で人が判断できる。しかし,実行速度はコードを実行して実際に時間を計測しなければわからない。場合によっては,実行速度が圧倒的に速いために可読性や記述量が多少悪くても最善の方法になることも考えられる。

POSIX原理主義を実践していくうえで,シェルスクリプトは実行速度が遅いという風評被害を受けることがある。これは,複数の実現方法の中から実行速度が遅いものを選択した場合や,実行速度の遅い方法しか知らない場合になされる批判だ。

そこで,POSIXに準拠したプログラムの実行速度の計測方法を検討し,実行速度が遅いという批判を避けられるようにする。

時間の計測方法

まず,実行速度の計測にあたって,計測する時間の種類を把握しておく。例えば,プログラムの開始時から終了時までなのか,プログラムの実際の処理時間だけをみるのかといったように,用途によって注目すべき項目が異なってくる。

POSIXにおける実行時間はtimeコマンドの節で説明されている3種類となる。

POSIXにおける実行時間の種類
種類説明
Real timeプログラムの呼び出しから終了までの時間。I/Oの待ち時間を含む。
User CPU timeプログラム自体の実行時間。
System CPU timeプログラムを実行するためのOSの処理時間。

Real timeはコマンド呼び出しから終了までの合計時間である。単に実行速度について議論するときはReal timeを指すことが多い。User CPU timeとSystem CPU timeに加え,これら2種類以外の全ての要素(I/Oやネットワークの待ち時間など)の+αの要素を含む。式で記述すると以下となる。

Real time = User CPU time + System CPU time + α

User CPU timeはコマンド自体の処理時間である。プログラム自体のパフォーマンスに注目する場合はこの時間を参照する。

System CPU timeはプログラムを実行するために必要なリソースの割当などのOS自体が処理する時間である。System CPU timeを参照することはあまりない印象だ。

計測時間の保証精度

計測方法の説明の前にもう一つ知っておく必要がある。それは,POSIXでの計測時間の保証精度だ。計測した時間の秒の内,小数点以下何桁までPOSIXで使えるとみていいかだ。

POSIXでのプロセスの時間計測にはsys/times.hで定義されるtimes関数を使われている。times関数のページで以下の記述がある。

All times are measured in terms of the number of clock ticks used.

...

Applications should use sysconf(_SC_CLK_TCK) to determine the number of clock ticks per second as it may vary from system to system.

times - XSH

つまり,時間の計測にはclock tick(クロック単位)を使っていることになる。そして,clock tickはシステムで異なるのでsysconf(_SC_CLK_TCK)で取得すべきだとのこと。clock tickは以下で定義される。

3.97 Clock Tick

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.
3.97 Clock Tick - Definitions - XBD

1秒間に発生する実装で定義される回数での時間の間隔。この回数で時間の間隔が処理されている模様。clock_tの値でclock tickの値を確認できるらしい。

実際にclock tickの値を確認してみる。以下のコードをgccでコンパイルして実行してみたところ,以下の結果になった。

  • MSYS2だと1000
  • Ubuntu 16.04だと100
clock tickの表示
////////////////////////////////////////////////////////////////////////////////
/// \file      clock_tick.c
/// \author    SENOO, Ken
/// \copyright CC0
////////////////////////////////////////////////////////////////////////////////

#include <stdio.h>
#include <unistd.h>

int main(void){
  printf("%ld\n", sysconf(_SC_CLK_TCK));
  return 0;
}

clock tickが確認できたところで,このclock tickの値と計測時間の精度をどう見るかを考える。timeコマンドに以下の説明があった。

The precision used may be less than the default six digits of %f, but shall be sufficiently precise to accommodate the size of the clock tick on the system (for example, if there were 60 clock ticks per second, at least two digits shall follow the radix character).

time - XCU

timeコマンドやtimesコマンドなど計測時間を表示するコマンドの表示結果の書式は%fという表記を使っており,ここの精度は基本的に処理系依存となる。しかし,上記説明で書かれている通り,この精度はclock tickのサイズに対応できなければならない。例にあるとおり60 clock ticksであれば,1/60≒0.0167であり0.01 sの単位までは保証されなければならないとある。

実際にclock tickを確認したところUbuntu 16.04で100だった。0.1 sの単位までの精度の保証で済むのはclock tick=10(1/10=0.1 s)までで,clock tick>11となれば1/11≒0.091 sとなり,0.01 sの精度の保証が必要となる。現実的にclock tick<=10は小さすぎるので0.1 sの単位の保証で済むとは考えにくい。

したがって,時間の計測時には小数点以下第2位である0.01 s(10 ms)の単位までは保証されると考えてよいだろう。

計測方法

ここからは,実際にPOSIXに準拠した実行時間の計測方法について説明する。以下の3通りの方法が存在する。

  1. date
  2. times
  3. time
date

dateコマンドには2種類の機能がある。

  • 現在日時の出力
  • システム日時の更新

この内,時間の計測には現在日時の出力を利用する。dateコマンドでの実行時間の計測手順は以下となる。

  1. 計測対象プログラムの実行前後でdateコマンドを実行
  2. dateコマンドの実行結果を変数に保存
  3. 実行前後の時間の差分により時間を計測
dateコマンドによる時間計測例
#!/bin/sh -u
## \file time-date.sh
start=$(date +%s)
sleep 1
stop=$(date +%s)
echo "$((stop - start))"
dateコマンドによる時間計測結果例
1

dateコマンドによる時間計測は,プログラムの実行前後の時間の差分をとるということで,直感的でわかりやすい。しかし,以下の欠点がある。

dateコマンドによる時間計測の欠点
  1. 最小計測単位が1 sであり精度が低すぎる。
  2. Real timeしか計測できない。

GNU coreutilsに含まれるdateコマンドではns(ナノ秒)を表現する%Nという記法がサポートされている。しかし,POSIXでは定義されていない。POSIXでの最小単位は秒(s)%Sである。たいていのコマンドは1 ms以内で動作するので,dateコマンドで測定するには秒の単位になるまで自分でループさせる必要がある。そして,時間計測のためにそれだけユーザーが待たなければならない。また,最小計測単位が1 sであり,有効数字が1桁であるので精度が悪い。例えば,計測して8 sだったとしても,この値はその一つ下の位である0.1 sの誤差を含んでおり信頼性が低い

実際に時間を計測する際には,マシンの状態も考慮して複数回試行する。1回の測定単位が秒だと1コマンドの測定にあたって少なくとも10秒程度かかる。これでは効率が悪すぎる。

また,Real timeしか計測できないので,本当にパフォーマンスがシビアなプログラムの計測では余計な待ち時間まで含んでしまうため,正確な速度がわからない。

times

timesコマンドはPOSIXのspecial built-in utilityとして定義されている。

このコマンドは引数を取らず,現在のプロセスと,全ての子プロセスの合計のUser CPU timeとSystem CPU timeを出力する。Real timeを出力しないところに注意する。

例えば,現在のシェルでtimesコマンドを入力すると,以下のように1行目に現在のプロセスのUser CPU timeとSystem CPU timeを表示し,2行目には全子プロセスの時間を表示する。

times
0m0.088s 0m0.052s
0m17.144s 0m1.552s

timesコマンドによる時間の計測はスクリプトの最後にtimesコマンドを実行して行う。

timesコマンドによる時間計測
#!/bin/sh -u
## \file time-times.sh yes | head -n 100000
times
timesコマンドによる時間計測結果例
0m0.000000s 0m0.000000s
0m0.000000s 0m0.020000s

また,コマンドライン上で行う場合は以下のようにshコマンドを起動してそこで処理するようにすればよい。

sh -c 'for i in $(yes | head -n 10000); do echo $i; done; times'

なお,shでの秒の出力結果の精度が6桁となっているが,実際のところ数字が表示されるのは小数第2位までだった。これは,計測時間の保証精度で議論したとおりの精度だ。

timesコマンドの欠点は以下となる。

timesコマンドによる時間計測の欠点

  1. Real timeが計測できない。
  2. 計測対象が親と子プロセスで分かれる。

一番必要と思われるReal timeを計測できないが残念だ。また,計測対象が親と子で分かれているのは利点でもあり欠点でもある。実行時間計測したいときは,通常全体の時間が問題になる。子プロセスの実行時間が必要であれば,そこだけ別で計測すればいいからだ。

timesコマンドは,dateコマンドのように自分で計算する必要がなくスクリプトの一番最後で実行するだけでよいので簡単だ。

参考:bash - How to get execution time of a script effectively? - Unix & Linux Stack Exchange
time

timeコマンドはコマンドの実行時間を計測するコマンドだ。引数で指定したコマンドを実行し,Real timeとUser CPU time,System CPU timeの全てを表示してくれる。

timeコマンドの表示結果の違い

timeコマンドをそのまま実行すると,環境によって表示結果が異なってしまう。これはbashやzshの構文としてtimeが存在するからだ。試しにいろんなシェルでのtimeの実行結果を以下の表に示す。

timeコマンドの表示結果例
シェルtime sleep 1の実行結果
dash
0.00user 0.00system 0:01.00elapsed 0%CPU (0avgtext+0avgdata 2116maxresident)k
0inputs+0outputs (0major+81minor)pagefaults 0swaps
bash
real    0m1.001s
user    0m0.000s
sys     0m0.000s
zsh
sleep 1  0.00s user 0.00s system 0% cpu 1.003 total
csh
0.0u 0.0s 0:01.00 0.0% 0+0k 0+0io 0pf+0w
tcsh
0.000u 0.000s 0:01.00 0.0%      0+0k 0+0io 0pf+0w
ksh
real 0m1.00s
user 0m0.00s
sys 0m0.00s

したがって,shebangが#!/bin/bash#!/bin/cshなどと書かれたシェルスクリプトではシェル構文のtimeが呼ばれてしまうので,表示結果がばらばらになってしまう。timeコマンドの表示結果を統一するには以下の手順をとる。

timeコマンドの表示結果の統一方法
  1. コマンドライン上などで使う場合は,timeコマンドをエスケープして(\time)明示的にコマンドを指定。
  2. -pオプションを指定して表示結果をPOSIXに準拠させる。

bashなどでtimeとそのまま入力すると組み込みコマンドが呼ばれてしまう。それを避けるために,以下のようにエスケープして明示的に外部コマンドのtimeを実行してやる。

\time sleep 1

また,timeコマンドの既定の表示結果はPOSIXで定義されていない。-pオプションを指定した場合のみ以下の形式で表示されることが規定されている。

real 1.00
user 0.00
sys 0.00

したがって,timeコマンドをシェルスクリプトで使う場合は-pオプションを常に付けるべきだろう。ただし,-pオプションをつけると表示される結果が小数点第2位までとなるので注意する。コマンドライン上でぱっと確認したいだけならば,bashやzshの組み込みのtimeコマンドの方が便利なのでそちらを使うのもありだろう。

timeコマンドの可搬性

2017-01-07追記:

IBM AIX 7.1ではtime -pとして実行した場合に,-pオプションを認識できず以下のようなエラーが出てしまう。

#!/bin/sh
time -p sleep 1
-p: Command not found.

これは,IBM AIXの/bin/shの実体がksh88となっているためだ。kshの組み込みのtimeには元々-pオプションは存在しない(cshとzshのtimeにも不在,bashのtimeには-pが存在)。しかし,ksh93であればtime -pとした場合,-pオプションを認識してシェル構文ではなく外部コマンドのtimeを実行してくれていたので大丈夫だった。本来の動作だと思うが,ksh88では常にtimeをシェル構文として扱うようで,-pをコマンドとみなしてしまうためにこのようなエラーが出てしまった。

シェル組み込みのtimeは,実は組み込みコマンドではなくcaseforのような予約語として存在するシェル構文となっている。このことは,typeコマンドの出力結果で確認できる。

bash
type time
type command
time is a shell keyword
command is a shell builtin

シェル構文はプロセスが新しく生成されないため,コマンドよりも実行速度が速く,本来であれば利用が推奨される。しかし,timeに関しては外部コマンドのtimeと名前が被ってしまい,シェル構文が優先されてしまうと,今回のように可搬性を高めるための-pオプションが使えなくなってしまう

これを回避するためには,クォートにより予約語を無効化する。この機能はPOSIXで明記されている。

Quoting is used to remove the special meaning of certain characters or words to the shell. Quoting can be used to preserve the literal meaning of the special characters in the next paragraph, prevent reserved words from being recognized as such, and prevent parameter expansion and command substitution within here-document processing (see Here-Document).

2.2 Quoting - XCU

以下のように,予約語の全体または一部分に対して,バックスラッシュでエスケープしたり,一重や二重の引用符('")で囲むと単語全体がクォートされ,予約語が無効化される。

\time
t\ime
t"im"e
ti'me'

この他に,以下のようにcommandコマンドを使って明示的に外部コマンドとしてtimeを実行することでも対応できる。しかし,記述の簡潔さからバックスラッシュでクォートするのがよいだろう。

command time -p sleep 1

IBM AIXのように/bin/shの実体としてksh88が使われている場合があるので,シェルスクリプトでtimeを使う場合は,出力形式を統一するために常に\time -pにより外部コマンドのtimeを使うべきだろう。

timeコマンドでの時間計測

timeコマンドで時間を計測する場合は,基本的に計測対象プログラムを引数に指定するだけでよい。

\time -p sleep 1

しかし,この方法だとパイプを含む場合そこで計測対象が終わってしまう。パイプを含む全体を計測対象とするには,timeコマンドの引数にシェルを指定し,そのシェルの中で実行させる。

\time -p sh -c 'for i in $(yes | head -n 10000); do echo "A" | grep -q "A"; done'

このシェルの中で実行させる方法だと,forやcaseなどのシェルの組み込み構文での速度計測にも使える。サブシェルで実行させなければ,いちいちスクリプトファイルに書き出してtimeコマンドを実行しないといけないのでこれは便利だ。

timeコマンドを使う場合,Real time,User CPU time,System CPU timeの全てを計測できる。また,引数に計測対象を指定するだけでよいので簡単だ。

その他の計測方法

POSIX非準拠だったり,時間計測としてはあまり適さないと判断した方法を参考までに掲載する。

/proc/uptime

まず,POSIXの範囲を超えるのならば,/proc/uptimeを使う方法がある。

この方法では,システム起動からの経過時間を最小単位10ミリ秒で取得可能とのこと。

この方法だと,POSIX非準拠になるうえ,測定可能な時間はReal timeだけとなる。多くのLinuxでは存在するので百歩譲って許容するとしても,自分で読み込みのためのスクリプトを書く必要があり手間である。

ps

psコマンドでも時間を測ることができる。

以下のコマンドのようにプロセスと表示させる項目を選択すれば,プロセスの処理時間を取得できる。

ps -o stime,time $$
STIME     TIME
20:03 00:00:00

この方法だと,最小単位が秒であり精度が低い。その割に,終了時間を得るのが煩雑になってしまう。

How to check how long a process has been running? - Unix & Linux Stack Exchange

C言語で自作

最後はPOSIXのC言語の範囲でプログラムを書くことだ。

実行時間の計測には,clock()getrusage()関数が使えるようなので,これらを使ったC言語プログラムを作成しても実現できるだろう。

しかし,C言語でやる場合は自分で書く必要があり,またコンパイルも必要となる。最後の手段にすべきだろう。

CPU time - Wikipedia

Discussion

ここまでで,実行時間の計測方法を紹介した。これらの中でどれがベストであるかを検討する。検討にあたって,時間計測結果に必要と考える以下2項目の対応状況を確認する。

  • ミリ秒の精度での計測
  • Real timeとUser CPU timeの計測

時間計測結果の対応状況を以下の表にまとめた。

実行時間の計測方法の比較
コマンド・方法計測最小単位Real timeUser CPU timeSystem CPU time
date +%s1 s××
times10 ms×
\time -p10 ms
/proc/uptime10 ms××
ps1 s××

この結果から,全ての条件を満たしている\time -pがプログラムの実行時間の計測方法として最善と判断した。実際,計測手順も簡単で応用しやすいので順当な結果だろう。

Conclusion

プログラムの実行時間のPOSIXに準拠した計測方法を紹介した。プログラムを書く上で,実行速度はとても重要な要素である。「シェルスクリプトは速度が遅い」などといわれないように,複数の実現方法が思いついたときtimeコマンドで時間を計測し,最善の方法を検討しよう。

最後に,冒頭で掲示した変数VARと文字列TARGETが一致するかの3通りの方法(testgrepcase)の実行速度の測定コードと測定結果を示す。

#!/bin/sh -u
## \file time-match.sh

N=20000 VAR=TARGET \time -p sh -c 'for i in $(yes | head -n $N); do [ "$VAR" = "TARGET" ] && echo MATCH; done' >/dev/null
N=20000 VAR=TARGET \time -p sh -c 'for i in $(yes | head -n $N); do printf %s "$VAR" | grep -q ^TARGET$ && echo MATCH; done' >/dev/null
N=20000 VAR=TARGET \time -p sh -c 'for i in $(yes | head -n $N); do case "$VAR" in TARGET) echo MATCH;; esac; done' >/dev/null
real 0.03
user 0.03
sys 0.00
real 15.38
user 0.19
sys 2.18
real 0.01
user 0.01
sys 0.00

組み込みコマンドのcaseが最も速く,grepによるものが最も遅い結果となった。このような結果になった理由を簡単に解説する。

caseはシェルの複合コマンド(Compound Commands,制御構造)であり,通常のコマンドと異なり新しいプロセスが生成されない。そのため,基本的に速度が速い。grepによるマッチでは文字列の出力のために他と比べて余分にコマンドを実行していることと,正規表現のマッチ自体の処理があるため遅くなったのだと思われる。

0 件のコメント:

コメントを投稿