シェルスクリプトのプロファイリング設計｜PS4変数とtimeでボトルネックを特定する方法

この記事のポイント

・PS4変数にEPOCHREALTIMEを設定すると行単位で実行時刻を記録できる
・BASH_XTRACEFDでトレース出力を別ファイルに分離して後から分析できる
・time { ... }でスクリプト内のフェーズ別に処理時間を計測できる
・prof_start/prof_end関数でコードを汚さずプロファイリングを組み込める

# スクリプト全体を計測する
time bash deploy.sh

# 実行結果例（server-prod-01 / RHEL 9.4）
real    0m4.523s
user    0m0.047s
sys     0m0.891s

#!/bin/bash

# %R = real経過時間（秒・小数点以下3桁）
# %U = userモードCPU時間  %S = sysモードCPU時間
TIMEFORMAT="[TIME] real=%Rs user=%Us sys=%Ss"

time {
    echo "processing..."
    sleep 1
    ls /var/log/ > /dev/null
}

# 出力例
# processing...
# [TIME] real=1.012s user=0.001s sys=0.004s

#!/bin/bash
TIMEFORMAT="[PROF] %Rs"

echo "=== フェーズ1: ファイル同期 ==="
time {
    rsync -a /src/ /backup/
}

echo "=== フェーズ2: ログ圧縮 ==="
time {
    find /var/log -name "*.log" -mtime +7 | xargs gzip
}

echo "=== フェーズ3: DBバックアップ ==="
time {
    mysqldump --single-transaction mydb > /backup/mydb_$(date +%Y%m%d).sql
}

# 実行結果例（server-prod-01 / RHEL 9.4）
# === フェーズ1: ファイル同期 ===
# [PROF] 1.247s
# === フェーズ2: ログ圧縮 ===
# [PROF] 4.831s    ← ここがボトルネック
# === フェーズ3: DBバックアップ ===
# [PROF] 2.156s

#!/bin/bash
# PS4にEPOCHREALTIMEを設定してset -xを有効にする
export PS4='+ [${EPOCHREALTIME}] ${BASH_SOURCE##*/}:${LINENO}: '
set -x

echo "start"
sleep 0.5
echo "end"

# 実行結果例（server-prod-01 / RHEL 9.4）
# + [1723867200.123456] deploy.sh:5: echo start
# start
# + [1723867200.124001] deploy.sh:6: sleep 0.5
# + [1723867200.625987] deploy.sh:7: echo end
# end

#!/bin/bash

# トレースログの保存先
TRACE_LOG="/tmp/trace_$(date +%Y%m%d_%H%M%S).log"

# ファイルディスクリプタ7番をトレースログに割り当てる
exec 7>"${TRACE_LOG}"
BASH_XTRACEFD=7

# PS4にタイムスタンプを設定
export PS4='+ [${EPOCHREALTIME}] ${BASH_SOURCE##*/}:${LINENO}: ${FUNCNAME[0]:+${FUNCNAME[0]}(): }'
set -x

# スクリプトの処理（コンソールには通常出力のみ表示される）
echo "処理開始"
for i in $(seq 1 100); do
    ls /var/log/ > /dev/null
done

# 計測終了・クローズ
set +x
exec 7>&-

echo "トレースを ${TRACE_LOG} に保存しました"

# トレースファイルの先頭を確認する
head -5 /tmp/trace_20260817_091500.log

# 実際の出力例（server-prod-01）
# + [1723867200.123456] backup.sh:12: sync_files(): rsync -a /src/ /backup/
# + [1723867204.567890] backup.sh:13: sync_files(): echo "sync complete"
# + [1723867204.568001] backup.sh:18: compress_logs(): find /var/log ...

# 0.1秒以上かかったコマンドだけ抽出する
awk -F'[][]' '/^\+/{
    ts = $2
    if (prev_ts != "") {
        diff = ts - prev_ts
        if (diff > 0.1) printf "[%.3f秒] %s
", diff, $0
    }
    prev_ts = ts
}' /tmp/trace_20260817_091500.log

#!/bin/bash
# --profileオプションで計測モードを有効化する
PROFILE_MODE=false
[[ "$1" == "--profile" ]] && PROFILE_MODE=true

# タイマー開始
prof_start() {
    "${PROFILE_MODE}" || return 0
    _PROF_START="${EPOCHREALTIME}"
    _PROF_LABEL="${1:-unknown}"
}

# タイマー終了・結果を標準エラー出力に報告
prof_end() {
    "${PROFILE_MODE}" || return 0
    local elapsed
    elapsed=$(printf "%.3f" "$(echo "${EPOCHREALTIME} - ${_PROF_START}" | bc -l)")
    echo "[PROF] ${_PROF_LABEL}: ${elapsed}秒" >&2
}

# ---- スクリプト本体 ----
main() {
    prof_start "ファイル同期"
    rsync -a /src/ /backup/
    prof_end

    prof_start "ログ圧縮"
    find /var/log -name "*.log" -mtime +7 | xargs gzip
    prof_end

    prof_start "DBバックアップ"
    mysqldump --single-transaction mydb > "/backup/mydb_$(date +%Y%m%d).sql"
    prof_end
}

main "$@"

# 通常実行（計測なし）
bash backup.sh

# プロファイリング有効化して実行
bash backup.sh --profile

# 出力例（server-prod-01 / RHEL 9.4 / 計測結果は標準エラー出力）
# [PROF] ファイル同期: 1.247秒
# [PROF] ログ圧縮: 4.831秒
# [PROF] DBバックアップ: 2.156秒

# bashのバージョンを確認する
bash --version
# GNU bash, version 4.4.20(1)-release (x86_64-redhat-linux-gnu)

# bash 4.x では EPOCHREALTIME が使えないため、
# PS4に date +%s.%N を組み合わせて代替する
# ただし date コマンドの起動コスト（数ms）が計測誤差になる点に注意
export PS4='+ [$(date "+%s.%N")] ${BASH_SOURCE##*/}:${LINENO}: '
set -x

#!/bin/bash
# 前処理（トレース不要）
preprocess

# 計測したいブロックだけ囲む
set -x
slow_function  # ボトルネックが疑われる関数
set +x

# 後処理（トレース不要）
cleanup