コマンドプロンプトでコマンド実行の時間を計測する

コマンド処理の実行時間を計測するための小物類を作ってみている。
WindowsにもMaesure-Commandというコマンドがあって

Maesure-Command {ping 127.0.0.1 -n 5} 

とかやると細かい時間を出力してくれるらしい（使ったことないので分からない）。
しかしあまり使いやすくないように思った。
例えばバッチファイルでループして処理を何度も実行してみて、それぞれの実行時間をログファイルに出力したい、ということは結構あると思う。 ログファイルのファイル名はバッチを実行した日付時刻の入っているユニークなファイル名で、タブ区切りなどで整形したい。 そんな時、バッチファイルだけではかなり面倒なのだが、プログラムを作ってしまえば簡単になる。
ダウンロード（中のbatを読んで少し編集するだけで計測できるようになるはず）
これは絶対役に立つ、、と思うがみんな案外コマンド実行時間の計測なんてしないのかな？
細かい説明は以下。

１．ログファイル名に使う日付時刻文字列を取得する

日付時刻をファイル名にする場合、コマンドで日付を取るとファイル名に出来ない文字が入っていたりするのでかなり面倒なテキスト処理が必要になる。 ここを参考に「echo %DATE%」でやっていたのだが、英語環境のWindowsで試したらガタガタになった。「echo %DATE%」はロケールによって日付のフォーマットが異なるので日本語環境で作ったバッチが英語環境では全然動かなかったのだ。なのでC++でexeを作る。名前はDateTime.exeとした。

#include <time.h>
#include <iostream>

int main(void)
{
   struct tm *nowTM;
   __time64_t nowtime;

   _time64(&nowtime);
   nowTM = _localtime64(&nowtime);   
   printf("%04d%02d%02d_%02d%02d%02d", nowTM->tm_year + 1900, nowTM->tm_mon + 1,
         nowTM->tm_mday, nowTM->tm_hour, nowTM->tm_min, nowTM->tm_sec);
   return 0;
}

ただ日付時刻を出力するだけなのでバッチファイルからは以下のように利用する。

:set_log_name
call DateTime > datetime.tmp
for /f %%a in (datetime.tmp) do (
    set LOG_NAME=%%a
)
del datetime.tmp
exit /b 

ラベルを付けて変数に設定するサブルーチンとしてまとめておくと良い。

２．開始時間と終了時間より、処理にかかった時間を取得する

これをバッチだけでやるのは考えるだけで面倒になるのでさっさとC++でexeを作る。名前はStopWatch.exeとした。

#include <Windows.h>
#include <iostream>
#include <fstream>

const char* startFile("StopWatch_start.tmp");

int main(int argc, char* argv[])
{
 if (argv[1] == NULL) {
  std::cout << "Usage:\n\tStopWatch {start|stop}" << std::endl;
  return 1;
 }

 DWORD time = GetTickCount();

 if (strcmp("start", argv[1]) == 0) {
  std::ofstream ofs(startFile);
  ofs << time;
  ofs.close();
 } else if (strcmp("stop", argv[1]) == 0) {
  std::ifstream ifsStart(startFile);
  if (!ifsStart.fail()) {
   char startStr[22];
   ZeroMemory(startStr, 22);
   ifsStart.read(startStr, 22);
   ifsStart.close();
   remove(startFile);   
   __int64 startTime = _atoi64(startStr);
   std::cout << time - startTime;
  } else {
   std::cout << "may be not started." << std::endl;
   return 1;
  }
 }
 return 0;
}

"StopWatch start"で起動すると現在の時間をファイルに記録。 "StopWatch stop"で起動すると記録された時間と現在の時間との差（経過時間）を出力し、ファイルは削除する。
バッチからの使用は以下のようにする。

call StopWatch start 
 REM ここに処理を記述（例としてpingを打つ）
 ping 127.0.0.1 -n 3
call StopWatch stop > result.txt
call :read_result result.txt
echo %RESULT%ms
exit /b

:read_result  %1
for /f %%a in (%1) do (
    set RESULT=%%a
)
del %1
exit /b

pingコマンドにかかる時間を出力する例。
経過時間をBatch内で整形して出力するには結果をファイルに書き込んで再度読み込んで、という作業が必要になる。その部分はサブルーチンにしておくと良い。
StopWatchコマンドは現在の時間を記録するか経過時間を出すかだけですぐプロセスが終了するので計測対象コマンドには影響を与えない。
StopWatchの方はいろいろやり方はありそうだがまぁこれが一番分かり易そうだと思った。


最後に2つのexeを使うバッチの例：

@Echo off
pushd %~dp0
setlocal

call :set_log_name

REM 結果をRESULTに設定して利用する例
call StopWatch start 
 REM ここに処理を記述（例としてpingを打つ）
 ping 127.0.0.1 -n 3
call StopWatch stop > result.txt
call :read_result result.txt
echo 結果1 %RESULT%ミリ秒 >> %LOG_NAME%.log

endlocal
popd
exit /b

REM ─ サブルーチン ─ 
REM 結果ファイルを読込んでRESULTに設定する。ついでに消す。
:read_result  %1
for /f %%a in (%1) do (
    set RESULT=%%a
)
del %1
exit /b

REM ─ サブルーチン ─
REM  日付_時刻をLOG_NAMEに設定する。
:set_log_name
call DateTime > datetime.tmp
for /f %%a in (datetime.tmp) do (
    set LOG_NAME=%%a
)
del datetime.tmp
exit /b

これで起動した日付時刻のファイル名のログにStopWatch startからStopWatch stopまでの時間が記録される。
exe2つとサンプルのバッチをまとめています（ダウンロード）。

ちなみにpingをローカルループバックアドレスに向けて打つと必ず1ms以内に返ってくる。また、Windowsのpingコマンドは1秒ごとにpingを送るように出来ている。これらを利用して、

ping 127.0.0.1 -n <回数>

で指定秒数の経過を待つ、という技がある。バッチにはsleepが無いのでこうしていたらしい。かっこいい（これをかっこいいと思ってしまう感覚あるよね？）。
今は「timeout <秒数>」で出来てしまうが。