0. はじめに
筆者は自作のコンソールプログラムをコマンドプロンプト上で実行することが多く,実行時間を計測することも多い。
以前「今さら森博嗣『笑わない数学者』のビリヤードの問題を解く」というシリーズ記事を手掛けていたころ,計算時間もプログラムの評価指標の一つであるから実行時間を正確かつ手軽に計測する必要があったのだ。
今さら森博嗣「笑わない数学者」のビリヤードの問題を解く(13)~総括編 - Qiita
1. ささっと作ってみる
ということで,コンソールプログラムの実行時間を計測するプログラムをバッチファイルで作った。現在の時刻は環境変数 TIME
で得られるので,プログラムの実行前後の時刻をそれぞれ記憶してこれらの差分を求めれば良い。環境変数 TIME
は 10:32:16.05
のように24時間制で 10ms の単位まで時刻が得られるので,それぞれ時刻 00:00:00
からの通算時間(ms単位)に変換し,それらの差分を求めることにより実行時間を ms 単位で求めることができる。
バッチファイルの中では set /a
コマンドで数値計算を行うことができるが,ゼロから始まる数値は八進数として扱われるので,十進数として計算するためには一桁ずつ分けて計算する必要がある。また,時間(hour)のみ一桁のときは上位桁にゼロではなく空白が入るので要注意だ。
プログラムの実行時間を計測するバッチファイル PROF.CMD バージョン 0.00
@echo off
if "%~1"=="" goto USAGE
set TIME1=%TIME%
%*
set TIME2=%TIME%
call :COUNT_TIME "%TIME1%" COUNT1
call :COUNT_TIME "%TIME2%" COUNT2
set /a DIFF=COUNT2-COUNT1
call :SPLIT_NUMBER %DIFF% STR
echo 実行時間:%STR%[ms]
exit /b
rem ------------------------------------------------------------------------
rem 【機能】時刻文字列を 00:00:00 からの通算時間に変換する
rem 【引数】時刻文字列 hh:mm:ss.uu
rem 【返値】00:00:00 からの通算時間(ms単位)
rem 【注意事項】時刻文字列は " h:mm:ss.uu" のように時間が一桁分しかない場合があり,
rem その場合は代わりに空白が占めているので,時刻文字列は二重引用符で囲むこと
rem ------------------------------------------------------------------------
:COUNT_TIME
setlocal
set STR=%~1
set STR=%STR: =0%
set HOUR1=%STR:~0,1%
set HOUR2=%STR:~1,1%
set MIN1=%STR:~3,1%
set MIN2=%STR:~4,1%
set SEC1=%STR:~6,1%
set SEC2=%STR:~7,1%
set MSEC1=%STR:~9,1%
set MSEC2=%STR:~10,1%
set /a HOUR=10*HOUR1+HOUR2
set /a MIN=10*MIN1+MIN2
set /a SEC=10*SEC1+SEC2
set /a MSEC=100*MSEC1+10*MSEC2
set /a COUNT=60*60*1000*HOUR+60*1000*MIN+1000*SEC+MSEC
endlocal&&set %2=%COUNT%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】数値を三桁ずつ区切る
rem 【引数】数値 123456789
rem 【返値】三桁ずつ区切られた数値 123,456,789
rem ------------------------------------------------------------------------
:SPLIT_NUMBER
setlocal
set STR=%~1
set RET=%STR:~-3%
:SPLIT_NUMBER_LOOP
set STR=%STR:~0,-3%
if "%STR%"=="" goto SPLIT_NUMBER_BREAK
set RET=%STR:~-3%,%RET%
goto SPLIT_NUMBER_LOOP
:SPLIT_NUMBER_BREAK
endlocal&&set %2=%RET%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】ヘルプメッセージ
rem ------------------------------------------------------------------------
:USAGE
echo コマンドの実行時間を計測します。
echo.
echo PROF(.CMD) [コマンド] [コマンドパラメータ] ...
exit /b
バッチファイルの中でサブルーチン COUNT_TIME
および SPLIT_NUMBER
を関数として使用している。要するに文字列を返値として返すテクニックを使用している。詳しくは参考文献のサイトを参照のこと。
2. 実行例
引数なしで実行するとヘルプメッセージが表示される。
c:\>prof
コマンドの実行時間を計測します。
PROF(.CMD) [コマンド] [コマンドパラメータ] ...
TIMEOUT
コマンドの実行例を示す。実行時間は ms 単位で三桁ずつコンマ区切りで表示される。
c:\>prof timeout /T 100
0 秒待っています。続行するには何かキーを押してください ...
実行時間:100,120[ms]
3. 改善ポイント
プログラムがある程度動くようになると,いろいろ改善したいポイントが見えてくる。
(1) プログラムの実行中に日が変わった場合に対応したい
先日のビリヤードの問題のときはちょうど一月から四月にかけて深夜にプログラムを実行していた。実行中に日が変わるのはザラのうえ,月が替わるときもあった。とくに今年は閏年で2月29日があり,計算がとても煩わしかった。
(2) 計測した時間を「時分秒」の形式でも表示したい
たとえば計算時間が 4,000,000[ms]
と表示されても分かりにくいからである。01:06:40
と表示されれば1時間強だと分かる。
(3) 計測した時間を標準エラー出力に出力したい
実行するプログラムによっては標準出力へ大量にデータを出力するようなものがある。このような場合,プログラムの出力をファイルにリダイレクトしたりするが,計測時間までも一緒にリダイレクトされてしまうのを防ぐため,計測時間は標準エラー出力に分けて出力したい。
(4) バッチファイルを呼び出せるようにしたい
バッチファイルを実行した場合,そのバッチファイルの実行終了と同時に呼び出し側のバッチファイル(時間計測プログラムのこと)も終了してしまう。終了の道連れを防ぐためには call
コマンドを介してバッチファイルを呼び出す必要がある。そのためには実行プログラムの種別を判別できなくてはならない。
4. 対応策
4.1 日替わり対応(修正ユリウス通日への換算)
現在の日付を環境変数 DATE
で得られるので,プログラムの実行前後の日付を記憶しておき,これらをそれぞれ修正ユリウス通日に換算し,それらの差分を求めてやればよい。
グレゴリオ暦で $y$ 年 $m$ 月 $d$ 日の修正ユリウス通日 $\text{MJD}$ は以下の式で表される。
\text{MJD} = \left\lfloor \frac{36525 \cdot y}{100} \right\rfloor
+ \left\lfloor \frac{y}{400} \right\rfloor
- \left\lfloor \frac{y}{100} \right\rfloor
+ \left\lfloor \frac{3059 (m - 2)}{100} \right\rfloor
+ d - 678912
ただし,$m \le 2$ の場合,
\left\{ \begin{aligned}
m & \leftarrow m + 12 \\
y & \leftarrow y - 1
\end{aligned} \right.
とする。バッチファイル内での処理を以下に示す。
rem ----------------------------------------------------------------------------
rem 【機能】年月日 yyyy/mm/dd を修正ユリウス通日に変換する
rem 【引数】年月日 yyyy/mm/dd
rem 【返値】修正ユリウス通日
rem ----------------------------------------------------------------------------
:JULIAN_DAY
setlocal
set STR=%~1
set YEAR=%STR:~0,4%
set MON1=%STR:~5,1%
set MON2=%STR:~6,1%
set DAY1=%STR:~8,1%
set DAY2=%STR:~9,1%
set /a MON=10*MON1+MON2
set /a DAY=10*DAY1+DAY2
if %MON% LEQ 2 (
set /a YEAR=YEAR-1
set /a MON=MON+12
)
set /a JDAY=36525*YEAR/100+YEAR/400-YEAR/100+3059*(MON-2)/100+DAY-678912
endlocal&&set %2=%JDAY%
exit /b
こうして得られた修正ユリウス通日の差分(単位は日)に $24 \times 60^2 \times 1000$ をかけて ms 単位に換算したものを加えればよい。
set DATE1=%DATE%
set TIME1=%TIME%
%*
set DATE2=%DATE%
set TIME2=%TIME%
call :JULIAN_DAY %DATE1% JDAY1
call :JULIAN_DAY %DATE2% JDAY2
call :COUNT_TIME "%TIME1%" COUNT1
call :COUNT_TIME "%TIME2%" COUNT2
set /a DIFF=24*60*60*1000*(JDAY2-JDAY1)+COUNT2-COUNT1
call :SPLIT_NUMBER %DIFF% STR
echo 実行時間:%STR%[ms]
バッチファイルの set /a コマンドで取り扱える数値は符号つき 32bit 整数であるから,取り扱える時間は最大で $2^{31}$ [ms] まで,すなわち
\frac{2^{31}}{24 \times 60^2 \times 10^3} = 24.85 \cdots
より 24 日間までは計測可能である。
環境変数 DATE
と TIME
を同時に取得できていないので,タイミングによっては計算に失敗する可能性があることを断っておく。
4.2 計測時間の「時分秒」表示
00:00:00
からの通算時間を時刻文字列に変換するサブルーチンを用意した。たいていの場合,実行時間は一日未満だと思われるので,その場合は「日」表示は行わないようにした。
rem ------------------------------------------------------------------------
rem 【機能】00:00:00 からの通算時間を時刻文字列に変換する
rem 【引数】00:00:00 からの通算時間(ms単位)
rem 【返値】時刻文字列 d[day] hh:mm:ss.uuu[s] (d > 0)
rem hh:mm:ss.uuu[s] (d = 0)
rem ------------------------------------------------------------------------
:CONVERT_TIME
setlocal
set DIFF=%~1
set /a MSEC=DIFF%%1000
set /a DIFF=(DIFF-MSEC)/1000
set /a SEC=DIFF%%60
set /a DIFF=(DIFF-SEC)/60
set /a MIN=DIFF%%60
set /a DIFF=(DIFF-MIN)/60
set /a HOUR=DIFF%%24
set /a DAY=(DIFF-HOUR)/24
set MSEC=00%MSEC%
set SEC=0%SEC%
set MIN=0%MIN%
set HOUR=0%HOUR%
if %DAY% EQU 0
set RET=%HOUR:~-2%:%MIN:~-2%:%SEC:~-2%.%MSEC:~-3%[s]
) else (
set RET=%DAY%[day] %HOUR:~-2%:%MIN:~-2%:%SEC:~-2%.%MSEC:~-3%[s]
)
endlocal&&set %2=%RET%
exit /b
呼び出し側は下記のようになる。
set DATE1=%DATE%
set TIME1=%TIME%
%*
set DATE2=%DATE%
set TIME2=%TIME%
call :JULIAN_DAY %DATE1% JDAY1
call :JULIAN_DAY %DATE2% JDAY2
call :COUNT_TIME "%TIME1%" COUNT1
call :COUNT_TIME "%TIME2%" COUNT2
set /a DIFF=24*60*60*1000*(JDAY2-JDAY1)+COUNT2-COUNT1
call :SPLIT_NUMBER %DIFF% STR1
call :CONVERT_TIME %DIFF% STR2
echo 実行時間:%STR1%[ms]/%STR2%
4.3 標準エラー出力への出力
標準出力を標準エラー出力にリダイレクトして出力するサブルーチンを作成した。以下は echo
コマンドの代わりに使用する。空行を出力したい場合には echo2.
を呼び出す。
rem ------------------------------------------------------------------------
rem 【機能】標準エラー出力にエコー
rem 【引数】文字列
rem 【注意事項】空行を出力したい場合は ECHO2. を呼び出すこと
rem ------------------------------------------------------------------------
:ECHO2
1>&2 echo %*
exit /b
:ECHO2.
1>&2 echo.
exit /b
使用例を以下に示す。echo
文をすべて call :ECHO2
文で置き換えてやればよい。
rem ------------------------------------------------------------------------
rem 【機能】ヘルプメッセージ
rem ------------------------------------------------------------------------
:USAGE
call :ECHO2 コマンドの実行時間を計測します。
call :ECHO2.
call :ECHO2 PROF(.CMD) [コマンド] [コマンドパラメータ] ...
exit /b
リダイレクト時の注意事項
echo %* 1>&2
とすると余計なスペースが一つ挟まれてしまうのでリダイレクト記号(場所はどこでも良いらしい)を先頭に持ってきた。
4.4 バッチファイルの呼び出し対応
まず,指定したコマンドのフルパス(拡張子を含む)を得るサブルーチンを作成した。たいていの場合,実行するコマンドの拡張子指定は省略するので,その場合は環境変数 PATHEXT
に従って拡張子を追加して検索する。指定したコマンドが指定したパス,あるいはカレントディレクトリに存在する場合は絶対パスを返す。存在しない場合は環境変数 PATH
を検索する。
rem ------------------------------------------------------------------------
rem 【機能】コマンドを検索してフルパスを得る
rem 【引数】コマンド名(絶対または相対パス,拡張子は省略可能)
rem 【返値】コマンドのフルパス名
rem ------------------------------------------------------------------------
:SEARCH_COMMAND
setlocal
if "%~x1"=="" (
for %%J in ( %PATHEXT% ) do (
for %%I in ( "%~1%%J" ) do (
if exist "%%~fI" (
set RET=%%~fI
goto SEARCH_COMMAND_RET
)
if not "%%~$PATH:I"=="" (
set RET=%%~$PATH:I
goto SEARCH_COMMAND_RET
)
)
)
) else (
if exist "%~f1" (
set RET=%~f1
) else (
for %%I in ( "%~1" ) do set RET=%%~$PATH:I
)
)
:SEARCH_COMMAND_RET
endlocal&&set %2=%RET%
exit /b
上記のサブルーチンを利用してコマンドのフルパスを得た後,コマンドの拡張子を取得する。コマンドの拡張子が .CMD
または .BAT
の場合,コマンドラインの先頭に call
文を追加して呼び出せばよい。
rem ------------------------------------------------------------------------
rem コマンドを検索してフルパスを得る
rem ------------------------------------------------------------------------
call :SEARCH_COMMAND "%~1" SCRIPT_PATH
if not defined SCRIPT_PATH (
call :ECHO2 コマンド %~1 が見つかりません!!
exit /b
)
rem ------------------------------------------------------------------------
rem コマンドの拡張子を取得する
rem ------------------------------------------------------------------------
for %%I in ( "%SCRIPT_PATH%" ) do set SCRIPT_EXT=%%~xI
if not defined SCRIPT_EXT (
call :ECHO2 コマンド %~1 の拡張子がありません!!
exit /b
)
rem ------------------------------------------------------------------------
rem コマンドを実行する
rem ------------------------------------------------------------------------
set COMMAND_LINE=%*
if /I "%SCRIPT_EXT%"==".CMD" set COMMAND_LINE=call %COMMAND_LINE%
if /I "%SCRIPT_EXT%"==".BAT" set COMMAND_LINE=call %COMMAND_LINE%
set DATE1=%DATE%
set TIME1=%TIME%
%COMMAND_LINE%
set DATE2=%DATE%
set TIME2=%TIME%
5. 実装コード
こうやって継ぎ足し継ぎ足しでプログラムを作っていくと,ささっと手早く作ったつもりなのに,いつの間にかそれなりに大きなプログラムになっていて驚くことがある。
プログラムの実行時間を計測するバッチファイル PROF.CMD バージョン 1.00
@echo off
setlocal
rem ------------------------------------------------------------------------
rem 引数なしの場合はヘルプメッセージを表示する
rem ------------------------------------------------------------------------
if "%~1"=="" goto USAGE
rem ------------------------------------------------------------------------
rem コマンドを検索してフルパスを得る
rem ------------------------------------------------------------------------
call :SEARCH_COMMAND "%~1" SCRIPT_PATH
if not defined SCRIPT_PATH (
call :ECHO2 コマンド %~1 が見つかりません!!
exit /b
)
rem ------------------------------------------------------------------------
rem コマンドの拡張子を取得する
rem ------------------------------------------------------------------------
for %%I in ( "%SCRIPT_PATH%" ) do set SCRIPT_EXT=%%~xI
if not defined SCRIPT_EXT (
call :ECHO2 コマンド %~1 の拡張子がありません!!
exit /b
)
rem ------------------------------------------------------------------------
rem コマンドの実行および実行時間を計測する
rem ------------------------------------------------------------------------
set COMMAND_LINE=%*
if /I "%SCRIPT_EXT%"==".CMD" set COMMAND_LINE=call %COMMAND_LINE%
if /I "%SCRIPT_EXT%"==".BAT" set COMMAND_LINE=call %COMMAND_LINE%
set DATE1=%DATE%
set TIME1=%TIME%
%COMMAND_LINE%
set DATE2=%DATE%
set TIME2=%TIME%
rem ------------------------------------------------------------------------
rem 実行時間を表示する
rem ------------------------------------------------------------------------
call :JULIAN_DAY %DATE1% JDAY1
call :JULIAN_DAY %DATE2% JDAY2
call :COUNT_TIME "%TIME1%" COUNT1
call :COUNT_TIME "%TIME2%" COUNT2
set /a DIFF=24*60*60*1000*(JDAY2-JDAY1)+COUNT2-COUNT1
call :SPLIT_NUMBER %DIFF% STR1
call :CONVERT_TIME %DIFF% STR2
call :ECHO2 実行時間:%STR1%[ms]/%STR2%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】年月日を修正ユリウス通日に変換する
rem 【引数】年月日 yyyy/mm/dd
rem 【返値】修正ユリウス通日
rem ------------------------------------------------------------------------
:JULIAN_DAY
setlocal
set STR=%~1
set YEAR=%STR:~0,4%
set MON1=%STR:~5,1%
set MON2=%STR:~6,1%
set DAY1=%STR:~8,1%
set DAY2=%STR:~9,1%
set /a MON=10*MON1+MON2
set /a DAY=10*DAY1+DAY2
if %MON% LEQ 2 (
set /a YEAR=YEAR-1
set /a MON=MON+12
)
set /a JDAY=36525*YEAR/100+YEAR/400-YEAR/100+3059*(MON-2)/100+DAY-678912
endlocal&&set %2=%JDAY%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】時刻文字列を 00:00:00 からの通算時間に変換する
rem 【引数】時刻文字列 hh:mm:ss.uu
rem 【返値】00:00:00 からの通算時間(ms単位)
rem 【注意事項】時刻文字列は " h:mm:ss.uu" のように時間が一桁分しかない場合があり,
rem その場合は代わりに空白が占めているので,時刻文字列は二重引用符で囲むこと
rem ------------------------------------------------------------------------
:COUNT_TIME
setlocal
set STR=%~1
set STR=%STR: =0%
set HOUR1=%STR:~0,1%
set HOUR2=%STR:~1,1%
set MIN1=%STR:~3,1%
set MIN2=%STR:~4,1%
set SEC1=%STR:~6,1%
set SEC2=%STR:~7,1%
set MSEC1=%STR:~9,1%
set MSEC2=%STR:~10,1%
set /a HOUR=10*HOUR1+HOUR2
set /a MIN=10*MIN1+MIN2
set /a SEC=10*SEC1+SEC2
set /a MSEC=100*MSEC1+10*MSEC2
set /a COUNT=60*60*1000*HOUR+60*1000*MIN+1000*SEC+MSEC
endlocal&&set %2=%COUNT%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】数値を三桁ずつ区切る
rem 【引数】数値 123456789
rem 【返値】三桁ずつ区切られた数値 123,456,789
rem ------------------------------------------------------------------------
:SPLIT_NUMBER
setlocal
set STR=%~1
set RET=%STR:~-3%
:SPLIT_NUMBER_LOOP
set STR=%STR:~0,-3%
if "%STR%"=="" goto SPLIT_NUMBER_BREAK
set RET=%STR:~-3%,%RET%
goto SPLIT_NUMBER_LOOP
:SPLIT_NUMBER_BREAK
endlocal&&set %2=%RET%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】00:00:00 からの通算時間を時刻文字列に変換する
rem 【引数】00:00:00 からの通算時間(ms単位)
rem 【返値】時刻文字列 d[day] hh:mm:ss.uuu[s] (d > 0)
rem もしくは hh:mm:ss.uuu[s] (d = 0)
rem ------------------------------------------------------------------------
:CONVERT_TIME
setlocal
set DIFF=%~1
set /a MSEC=DIFF%%1000
set /a DIFF=(DIFF-MSEC)/1000
set /a SEC=DIFF%%60
set /a DIFF=(DIFF-SEC)/60
set /a MIN=DIFF%%60
set /a DIFF=(DIFF-MIN)/60
set /a HOUR=DIFF%%24
set /a DAY=DIFF/24
set MSEC=00%MSEC%
set SEC=0%SEC%
set MIN=0%MIN%
set HOUR=0%HOUR%
if %DAY% EQU 0 (
set RET=%HOUR:~-2%:%MIN:~-2%:%SEC:~-2%.%MSEC:~-3%[s]
) else (
set RET=%DAY%[day] %HOUR:~-2%:%MIN:~-2%:%SEC:~-2%.%MSEC:~-3%[s]
)
endlocal&&set %2=%RET%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】コマンドを検索してフルパスを返す
rem 【引数】コマンド名(絶対または相対パス,拡張子は省略可能)
rem 【返値】コマンドのフルパス名
rem ------------------------------------------------------------------------
:SEARCH_COMMAND
setlocal
if "%~x1"=="" (
for %%J in ( %PATHEXT% ) do (
for %%I in ( "%~1%%J" ) do (
if exist "%%~fI" (
set RET=%%~fI
goto SEARCH_COMMAND2
)
if not "%%~$PATH:I"=="" (
set RET=%%~$PATH:I
goto SEARCH_COMMAND2
)
)
)
) else (
if exist "%~f1" (
set RET=%~f1
) else (
for %%I in ( "%~1" ) do set RET=%%~$PATH:I
)
)
:SEARCH_COMMAND2
endlocal&&set %2=%RET%
exit /b
rem ------------------------------------------------------------------------
rem 【機能】標準エラー出力にエコー
rem 【引数】文字列
rem 【注意事項】空行を出力したい場合は ECHO2. を呼び出すこと
rem ------------------------------------------------------------------------
:ECHO2
1>&2 echo %*
exit /b
:ECHO2.
1>&2 echo.
exit /b
rem ------------------------------------------------------------------------
rem 【機能】ヘルプメッセージ
rem ------------------------------------------------------------------------
:USAGE
call :ECHO2 コマンドの実行時間を計測します。
call :ECHO2.
call :ECHO2 PROF(.CMD) [コマンド] [コマンドパラメータ] ...
exit /b
6. 実行例
実行例を以下に示す。下記のように実行プログラム billiard の出力後に実行時間を表示する。
prof billiard 12
(1) 1 2 9 8 14 4 43 7 6 10 5 24
(2) 1 2 12 31 25 4 9 10 7 11 16 5
(3) 1 2 14 4 37 7 8 27 5 6 13 9
(4) 1 2 14 12 32 19 6 5 4 18 13 7
(5) 1 3 8 9 5 19 23 16 13 2 28 6
(6) 1 3 12 34 21 2 8 9 5 6 7 25
(7) 1 3 23 24 6 22 10 11 18 2 5 8
(8) 1 4 7 3 16 2 6 17 20 9 13 35
(9) 1 4 16 3 15 10 12 14 17 33 2 6
(10) 1 4 19 20 27 3 6 25 7 8 2 11
(11) 1 4 20 3 40 10 9 2 15 16 6 7
(12) 1 5 12 21 29 11 3 16 4 22 2 7
(13) 1 7 13 12 3 11 5 18 4 2 48 9
(14) 1 8 10 5 7 21 4 2 11 3 26 35
(15) 1 14 3 2 4 7 21 8 25 10 12 26
(16) 1 14 10 20 7 6 3 2 17 4 8 41
(17) 1 15 5 3 25 2 7 4 6 12 14 39
(18) 1 22 14 20 5 13 8 3 4 2 10 31
実行時間:11,390[ms]/00:00:11.390[s]
実行プログラム billiard の出力をリダイレクトしても実行時間は表示される。
prof billiard 17 > nul
実行時間:1,122,292,520[ms]/12[day] 23:44:52.520[s]
バッチファイルを実行した場合,一例として自分自身を呼び出した場合を示す。
prof prof
コマンドの実行時間を計測します。
PROF(.CMD) [コマンド] [コマンドパラメータ] ...
実行時間:30[ms]/00:00:00.030[s]