コマンドの実行時間を計測してスクリプトのボトルネックを特定する手順

実行時間の計測がボトルネック特定の第一歩

シェルスクリプトの処理が遅い場合、感覚で「あの部分が原因だろう」と推測しても的外れになりがちです。まず計測して数値を確認することが、改善への最短ルートです。

Linux には実行時間を手軽に測る手段がいくつか用意されています。単一コマンドの合計時間だけでなく、スクリプト内の複数箇所で時刻を記録することで、どのブロックに時間が集中しているかを絞り込めます。

time コマンドで単一コマンドの実行時間を確認する

最も手軽な計測方法は time コマンドです。測りたいコマンドの前に time を付けるだけで、終了後に経過時間が表示されます。

time find /var/log -name "*.log" -mtime -7

実行すると次のような出力が得られます。

real    0m2.341s
user    0m0.023s
sys     0m0.198s

出力される3行の意味は次のとおりです。

• real：コマンド開始から終了までの経過時間（壁時計上の時間）
• user：ユーザー空間での CPU 使用時間
• sys：カーネル空間での CPU 使用時間

「実際に遅いと感じる時間」は real の値に対応します。real が大きく user + sys が小さい場合は、ディスク I/O やネットワーク待ちが原因である可能性があります。

time はシェル組み込みコマンドとして動作することが多く、パイプを含む複合コマンドを測る際は { } でまとめると正確に計測できます。

time { grep -r "ERROR" /var/log/app/ | sort | uniq -c; }

スクリプト内の複数箇所で経過時間を記録する

スクリプト全体の時間だけではどのブロックが遅いかわかりません。複数の計測ポイントを設けることで、ボトルネックの場所を絞り込めます。

$SECONDS 変数を使う方法

bash には $SECONDS という特殊変数があり、シェルが起動してからの秒数を整数で返します。処理の前に SECONDS=0 でリセットし、処理後に値を参照することで各ブロックの所要時間を確認できます。

#!/bin/bash

SECONDS=0
# 処理A
rsync -a /data/src/ /data/dst/
echo "処理A（rsync）: ${SECONDS}秒"

SECONDS=0
# 処理B
gzip -r /data/dst/
echo "処理B（gzip）: ${SECONDS}秒"

$SECONDS は秒単位の整数のみを返します。1秒未満の処理は「0秒」と表示されるため、細かく測りたい場合は次の方法を使います。

date コマンドでミリ秒単位の計測

date +%s%N はエポック秒とナノ秒を連結した値を返します。差分を求めてから 1,000,000 で割ると、ミリ秒単位の経過時間に変換できます。

#!/bin/bash

start=$(date +%s%N)

# 測りたい処理
python3 /opt/scripts/batch_import.py

end=$(date +%s%N)
elapsed=$(( (end - start) / 1000000 ))
echo "経過時間: ${elapsed} ms"

なお、date +%N（ナノ秒）は macOS 標準の date では対応していないため、この方法は Linux 環境専用です。

bash のトレース機能でより細かく追う

どのコマンドがいつ実行されているかをログに残したい場合、bash のデバッグトレース機能が役立ちます。PS4 変数にタイムスタンプを仕込んでから set -x を有効にすると、各行の実行時刻が出力されます。

#!/bin/bash
PS4='+ $(date "+%T.%N") '
set -x

rsync -a /data/src/ /data/dst/
gzip -r /data/dst/

set +x

出力は次のようになります（想定例）。

+ 12:34:56.123456789 rsync -a /data/src/ /data/dst/
+ 12:34:59.987654321 gzip -r /data/dst/

出力量が多くなる場合はファイルにリダイレクトしておくと後から確認しやすくなります。

bash -x script.sh 2>trace.log

よくあるつまずきと注意点

1回の計測結果だけで判断しない

OS のページキャッシュ効果により、2回目以降の実行はディスクアクセスが減り、初回より大幅に速くなることがあります。条件を揃えて複数回測定し、傾向を見ることが重要です。キャッシュを無効化して測りたい場合は sync; echo 3 > /proc/sys/vm/drop_caches でキャッシュを破棄してから実行する方法があります（root 権限が必要です）。

ループ内で date を毎回呼び出さない

ループ内で毎回 date +%s%N を呼ぶと、コマンド起動のオーバーヘッドが積み重なり計測値に影響が出ます。ループ回数が多い場合は、ループの開始・終了の2点だけを記録する方法に切り替えると、より正確な数値が得られます。

real が長くても user が短い場合は I/O を疑う

一般的に、real と user + sys の差が大きいときは CPU ではなく I/O 待ちや外部プロセスの完了待ちが支配的です。その場合は iostat や iotop でディスクの状況を確認するのが次のステップになります。

計測結果をもとに改善する流れ

実行時間の計測は、改善のサイクルに組み込んで初めて意味を持ちます。次の手順で進めると整理しやすいです。

1. スクリプト全体の実行時間を time で確認する
2. 処理をブロック単位に区切り、各ブロックの時間を $SECONDS または date +%s%N で記録する
3. 時間が集中しているブロックを特定する
4. 対象ブロック内で set -x トレースを使ってさらに細かく絞り込む
5. 対策（並列化・キャッシュ活用・不要な繰り返しの削減）を実施し、同じ方法で再測定する

「なんとなく遅い」という状態から脱するためには、まず数値を取ることが出発点です。計測用のコードは確認が終わったらコメントアウトまたは削除しておくと、通常実行時のログが汚れずに済みます。