(今さら) vmstat の結果に時間をつけてファイルに出力する

なんか、以前のプロジェクトでも、同じことをやった。なんで vmstat の結果に時間をつけてファイルに出力しなければならなかったかは忘れたが、、パフォーマンステストのエビデンスに必要だったのだろう。sar*1なんて高級なコマンドは知らなかったし。まぁ、そもそもLinuxではなかったし。
こんな簡単そうなことなのだが、けっこうはまった。


次を実行すれば、3秒おきに結果がコンソールに出力される。オプション -n は、ヘッダを何度も出力しないようにするためのもの。ファイルに出力しなくてよいなら(またはコンソールのログをとっておけばよいなら)、これで終わり。

# vmstat -n 3 | awk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 }'

3秒おきに10回出力してみる。もちろんうまくいく。

# vmstat -n 3 10 | awk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 }'

vmstat の結果を、そのままファイルにリダイレクトする。適当なところで vmstat を強制終了するのだが、うまくいく。

# vmstat -n 3 >> vmstat.log

3秒おきに10回出力した結果を、時刻つきでファイルにリダイレクトする。これもうまくいく。

# vmstat -n 3 10 | awk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 }' >> vmstat.log

で、次はどうだろうか?
もちろん、適当なところで vmstat を強制終了する。

# vmstat -n 3 | awk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 }' >> vmstat.log

これがうまくいかない。結果、ファイルには何も出力されない。もっと、単純化して、次がうまくいかない。

# vmstat 3 | grep '.*' >> vmstat.log

exec コマンドで、標準出力を完全にファイルに向けてもダメ。


なぜかはわからないのだが、ファイルへの書き込みが、パイプ後ろのプロセス(上記なら awkgrepが終了してから行われているようだ。なので、3秒おきに10回出力した結果は、awk が正常終了した後に、ファイルへ書き込まれる。途中で vmstat を強制終了した場合には、ファイルへは何も書き込まれない。


仕方なく、次のシェルを書いて、このシェルをバックグラウンドで実行することにした(ように記憶している)。

while :
do
    _line=`vmstat -n 1 3 | tail -n 1`
    _date=`date '+%Y/%m/%d %H:%M:%S'`
    echo "${_date} ${_line}" >> vmstat.log
done

ここで、“vmstat | tail -n 1”としないことがポイントだ。vmstat の1行目の情報は、まるで信用ならない。ウソだと思うなら、vmstat を連続で10回実行してみてほしい。CPU使用率とか、結果の数値に全く変化がないはずだ。でも vmstat 1 10 と実行すると、みるみる変化する。これで、再びはまったのだ。


これらを忘れて、まぁたドはまりするところだった。危ない危ない。
今回はRHELなんで、全部 sar を仕込んで解決させるんだけどね。こいつぁ便利だからさぁ。


2011/06/02追記

Roccoさんよりアドバイスをいただき、試してみた。
gawk で、fflusu() 関数を使えばパイプがリフレッシュされるとのことで、次のようにしたらうまくいった。

# vmstat -n 3 | gawk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 } { fflush() }' >> vmstat.log

awk でも、system() 関数を使えばパイプがリフレッシュされるとのことで、(ちょっときたないが)次のようにしたらうまくいった。

# vmstat -n 3 | awk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 } { system(":") }' >> vmstat.log

ありがとうございました。

*1:使い方は http://www.syboos.jp/linux/doc/sar-command.html がわかりやすい。