⌛️ hook29,866件を7日計測したら、毎ターン2.5秒待たせる犯人は自分のコストガードでした

前作のプロジェクト台帳とsymlinkツリーの話に続く、Claude Code環境シリーズです。

hookを足し続けていたある日、プロンプトを送ってから返事が始まるまでに、謎の2〜3秒の間があることに気づきました。それが毎ターンです。でも、どのhookのせいなのか分からない。hookはClaude Codeの内側から呼ばれるので、エラーにならない限りログを1行も残してくれません。

そこで実行時間をJSONLに書き出すラッパーを1本だけ挟み、7日で29,866件集めました。犯人は1本だけで、しかも私が自分で仕込んだものでした笑。数字は全部出します。

10本以上あるhookの、どれが遅いのか

いまの環境には10種類以上のhookが入っています。

• UserPromptSubmit（コストガード、モデルルーティング通知、コンテキスト読み込み）
• PreToolUse(Edit|Write)（シークレットスキャン、.env保護）
• PreToolUse(Bash)（gitコマンドガード）
• SessionStart（スキル自動更新、Obsidian文脈読み込み）
• MessageDisplay（フィルタリング）

同期で動くhookは、終わるまでClaude Codeを止めます。待たされている2秒の犯人は、この中にいるわけです。でもcost_guard.shなのかobsidian_context.shなのか、1本ずつ外して試すのは現実的ではありませんでした。非エンジニアの私が勘で疑っていっても、外れたら1日が終わるだけです。

📕 AIエージェントと自動化の全工程をまとめた総集編

手順・コード・テンプレをそのまま渡しています
🤖【完全版】月商160万円の「寝てても回る仕組み」をゼロから30日で組む全工程｜2026年10月版・Claude Code×AIエージェント・特典40ファイル・毎月更新

計測は、ラッパー1本で足りました

実体は ~/.claude/scripts/hook-latency-wrap.sh です。

#!/usr/bin/env bash
# hook-latency-wrap.sh : 任意のhookをラップして実行時間をJSONLに記録
set -uo pipefail

HOOK_BIN="${1:-}"
[ -z "$HOOK_BIN" ] && { echo "usage: $0 <hook> [args...]" >&2; exit 64; }
shift || true

LOG_DIR="$HOME/.claude/logs"; mkdir -p "$LOG_DIR"
JSONL="$LOG_DIR/hook-latency.jsonl"

# EPOCHREALTIME = bash 5+ の組み込み変数（秒.マイクロ秒）
start_us=$(printf '%s' "${EPOCHREALTIME//./}" | sed 's/^0*//')
[ -z "$start_us" ] && start_us=$(python3 -c 'import time;print(int(time.time()*1000000))')

"$HOOK_BIN" "$@"
exit_code=$?

end_us=$(printf '%s' "${EPOCHREALTIME//./}" | sed 's/^0*//')
[ -z "$end_us" ] && end_us=$(python3 -c 'import time;print(int(time.time()*1000000))')

elapsed_ms=$(( (end_us - start_us) / 1000 ))
printf '{"ts":"%s","hook":"%s","elapsed_ms":%d,"exit_code":%d}\n' \
  "$(date -u +%Y-%m-%dT%H:%M:%S)" "$(basename "$HOOK_BIN")" "$elapsed_ms" "$exit_code" >> "$JSONL"

exit "$exit_code"

決めたことは2つだけ

1つ目は、時刻を取るのにpythonを呼ばないことです。date +%s%N はLinux専用で、macOSのdateはナノ秒を返しません。bash 5以降なら、組み込み変数 $EPOCHREALTIME で 1716912345.678901 のように秒とマイクロ秒が一度に取れます。測るたびにpythonを起動していたら、計測そのものが遅さの原因になるところでした。危なかったです！

2つ目は、元のexit codeをそのまま返すことです。hookがexit 2を返すと、Claude Codeはその操作をブロックします。ラッパーが毎回0を返せば、その合図は消えてしまう。ここを雑にすると「gitガードを素通りさせる計測ツール」ができあがります笑。ラッパーは時間を測るだけで、hook本体の挙動には触りません。

settings.jsonは1行書き換えるだけ

// 変更前
{ "type": "command", "command": "~/.claude/hooks/cost_guard.sh" }

// 変更後
{ "type": "command",
  "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/cost_guard.sh" }

これで呼び出しのたびに、~/.claude/logs/hook-latency.jsonl へ1行ずつ溜まっていきます。

{"ts":"2026-06-21T20:10:41","hook":"cost_guard.sh","elapsed_ms":5196,"exit_code":0}
{"ts":"2026-06-21T20:10:33","hook":"obsidian_context.sh","elapsed_ms":827,"exit_code":0}
{"ts":"2026-06-21T20:11:18","hook":"skills-auto-update.sh","elapsed_ms":45705,"exit_code":0}

集計で見るのはp95だけ

hook-latency-report.sh [days]（既定は直近7日）の中身です。

python3 - "$JSONL" "$DAYS" <<'PY'
import sys, json, datetime, collections
log, days = sys.argv[1], int(sys.argv[2])
cutoff = datetime.datetime.now() - datetime.timedelta(days=days)

stats, fail = collections.defaultdict(list), collections.Counter()
with open(log) as f:
    for line in f:
        try:
            r = json.loads(line)
            if datetime.datetime.fromisoformat(r["ts"]) < cutoff: continue
            stats[r["hook"]].append(r["elapsed_ms"])
            if r.get("exit_code", 0) != 0: fail[r["hook"]] += 1
        except Exception:
            continue

rows = []
for hook, vals in stats.items():
    v = sorted(vals); n = len(v)
    p95 = v[min(n-1, int(n*0.95))]
    rows.append((hook, n, sum(v)//n, p95, v[-1], fail.get(hook, 0)))
rows.sort(key=lambda r: -r[3])  # p95降順

for hook, n, mean, p95, mx, fl in rows:
    flag = " ⚠" if p95 > 1500 else ""
    print(f"{hook:<32} {n:>5} {mean:>6}ms {p95:>6}ms {mx:>6}ms {fl:>5}{flag}")
PY

⚠を立てる閾値は、p95で1,500msにしました。同期hookは、その時間まるごと私を待たせます。プロンプトを打つたびに1.5秒止まると、体感で「重い」に入るラインです。

平均と最大は採りませんでした。平均は、速く終わる大多数に薄められてスパイクが見えなくなります。最大は、スリープ明けやゾンビプロセスの1回で跳ね上がり、ふだんの体感とかけ離れます。p95は「100回中95回はこの時間以内」という数字です。毎日の遅さをそのまま映してくれたのは、結局これでした。

7日・29,866レコードの実測

=== hook latency (last 7d, 29866 records) ===
hook                                 n    mean     p95     max  fail
----------------------------------------------------------------------
skills-auto-update.sh              365  46659ms  46114ms 1073920ms     0 ⚠
cost_guard.sh                     1493    605ms   2518ms   5802ms     0 ⚠
obsidian_context.sh                728  27816ms    782ms 19636398ms     1
model_routing_reminder.sh           23    148ms    451ms    641ms     0
pre_secrets_check.sh              2642     90ms    235ms   5561ms     0
user_prompt_submit.sh             1494     73ms    210ms    997ms     0
pre_env_guard.sh                  2642     59ms    154ms   4754ms     0
pre_git_guard.sh                  5726     43ms    117ms   2665ms     2
message_display_filter.sh        14753     47ms     96ms   5859ms     0

⚠が立った2本は、意味が真逆でした

skills-auto-update.shはp95が46秒。数字を見た瞬間、ヒヤッとしました！ SessionStartのたびに、45秒かけてスキル一覧をgit pullしています。ただ "async": true を付けてあるので、Claude Codeはこれを待ちません。つまり無害です。逆にasyncを付け忘れていたら、起動のたびに45秒固まっていたことになります。そっちの方がよほど怖い話でした。

cost_guard.shはp95が2,518ms、最大5.8秒。犯人はこっちでした。UserPromptSubmitの同期hookで、プロンプトを打つたびにccusageを呼んでプラン枠を確認しています。それが毎ターン走っていたわけです。送信から返事までの謎の2〜3秒は、自分で仕込んだコストガードでした。犯人、私です笑。

meanが27秒のhookは、狂っていたのが記録の方だった

obsidian_context.shは、meanが27,816ms（27秒！）なのにp95は782msです。最初は読み間違いを疑って、3回見直しました。原因は、Macのスリープ中にhookがゾンビとして生き残っていたこと。スリープ明けにまとめて記録されたレコードが混じっていました。exit codeが1のレコードが1件あるのも、スリープ明けの失敗と合います。meanは捨てて、782msを実態として扱いました。SessionStartで少し待ちますが、許容範囲です。

踏んだ落とし穴

• $EPOCHREALTIME から小数点を消すと、先頭にゼロが残ります。sed 's/^0*//' を挟まないと、整数変換でシェルが怒ります
• macOS標準の /bin/bash は4系で、$EPOCHREALTIME が空になります。echo "${BASH_VERSION}" で確かめて、5系を入れるかpython3のフォールバックに任せます
• async付きのhookも計測はできます。forkされたまま走るので、elapsed_msは正しく残ります。ただブロック時間はゼロなので、⚠が出ても運用上は無害です。asyncかsyncかを先に見ないと、数字を読み違えます
• exit codeを返さないラッパーは事故のもとです。常にexit 0だと、pre_git_guard.shが止めたはずのコマンドが通ってしまいます
• JSONLは7日で5.8MBに育ちました。放置すると半年で100MBを超えるので、logrotateかlaunchdで定期的に切り詰める必要があります

まとめ

• ラッパー1本で hook-latency.jsonl に実行時間を残し、hook-latency-report.sh でhookごとにcount/mean/p95/maxを集計。p95が1,500msを超えたら⚠
• 46秒かかるskills-auto-update.shはasyncなので無害。毎ターン2.5秒止めていたcost_guard.shが、体感の遅さの犯人
• meanはゾンビプロセスとスリープ明けで簡単に崩れるので、見るのはp95
• asyncかsyncかで同じ数字でも意味が変わるので、読む前にそこを確かめる

次回は、このJSONLを根拠にcost_guard.shを非同期にした話です。同期をやめるかわりに何を手放すのか、「止めてでも先に確認したいこと」をどう守るのかを書きます。

📕 この記事の内容を、実装まで全部まとめた有料記事があります 手順・コード・テンプレをそのまま渡しています AIで「寝てても回る仕組み」をゼロから30日で組む全手順