0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@bokuwalily

Claude Codeのhookが遅い原因を特定する ― wrap 1行でp95を計測

0
Last updated at Posted at 2026-06-24

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

hookを増やしていくと「なんか重くなった」という感覚が出てきます。ターンとターンの間に謎の間がある、プロンプトを打ってから応答が始まるまでが長い。でも「どのhookが原因か」を突き止めるのが難しい。hookはClaude Codeの内部から呼ばれ、エラーでなければ何もログに出ないからです。この記事では、hookの実行時間をJSONLに書き出すラッパー1本と、それを集計するスクリプトを紹介します。実測値も全部出します。

困りごと：hookが重いのは分かるが、どのhookかが分からない

私のClaude Code環境には現時点で10種類以上のhookが刺さっています。

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

hookが同期実行の場合、完了するまでClaude Codeはブロックします。「cost_guard.sh が毎回重いのか」「それとも obsidian_context.sh か」を手で追うのは無理です。

計測の仕組み：$EPOCHREALTIME ラッパー1本

~/.claude/scripts/hook-latency-wrap.sh がラッパーの実体です。

#!/usr/bin/env bash
# hook-latency-wrap.sh — 任意の hook をラップして実行時間を JSONL に記録
# 使い方: settings.json の command を以下に置き換える
#   "command": "~/.claude/scripts/hook-latency-wrap.sh /path/to/hook.sh"

set -uo pipefail

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

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

# EPOCHREALTIME = bash 5+ で SS.NNNNNN 形式（秒.マイクロ秒）
start_us=$(printf '%s' "${EPOCHREALTIME//./}" | sed 's/^0*//')
# 万一 EPOCHREALTIME が空(bash <5)なら python フォールバック
[ -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 ))
hook_name=$(basename "$HOOK_BIN")
ts=$(date -u +%Y-%m-%dT%H:%M:%S)

printf '{"ts":"%s","hook":"%s","elapsed_ms":%d,"exit_code":%d}\n' \
  "$ts" "$hook_name" "$elapsed_ms" "$exit_code" >> "$JSONL"

exit "$exit_code"

設計上のポイントが2つあります。

① $EPOCHREALTIME で python を呼ばない。date +%s%N はLinuxでしか動かず、macOSの date はナノ秒をサポートしません。bash 5以降の組み込み変数 $EPOCHREALTIME は 1716912345.678901 形式で秒＋マイクロ秒を返します。macOS Ventura以降なら /bin/bash --version が 5.x なので標準で使えます。

② exit "$exit_code" で元のexit codeを透過する。hookがexit 2を返せばClaude Codeがブロック・エラー表示するはずですが、ラッパーが常に0を返すとその情報が消えます。計測専用のラッパーなのでhook本体の動作には一切手を加えません。

settings.json への差し込み方

既存のhookコマンドをそのままラッパーに渡すだけです。前後の構造は変えません。

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

// 変更後（1行変えるだけ）
{
  "type": "command",
  "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/cost_guard.sh"
}

実際の ~/.claude/settings.json の該当部分はこうなっています。UserPromptSubmit に刺さっている3本が全てラップされています。

"UserPromptSubmit": [
  {
    "hooks": [
      {
        "type": "command",
        "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/user_prompt_submit.sh"
      },
      {
        "type": "command",
        "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/cost_guard.sh"
      },
      {
        "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/model_routing_reminder.sh",
        "type": "command"
      }
    ]
  }
]

これで毎回のhook呼び出しが ~/.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}

集計スクリプト：hook-latency-report.sh

~/.claude/scripts/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 = collections.defaultdict(list)
fail = collections.Counter()
total_records = 0
with open(log) as f:
    for line in f:
        try:
            r = json.loads(line)
            ts = datetime.datetime.fromisoformat(r["ts"])
            if ts < cutoff:
                continue
            total_records += 1
            stats[r["hook"]].append(r["elapsed_ms"])
            if r.get("exit_code", 0) not in (0, ):
                fail[r["hook"]] += 1
        except Exception:
            continue

rows = []
for hook, vals in stats.items():
    vals_sorted = sorted(vals)
    n = len(vals_sorted)
    p95 = vals_sorted[min(n-1, int(n*0.95))]
    rows.append((hook, n, sum(vals_sorted)//n, p95, vals_sorted[-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 を超えたら ⚠ を表示するのが判断基準です。Claude Codeの同期hookはこの時間だけユーザーをブロックします。プロンプトを打つたびに1.5秒待たされると、体感として「重い」と感じる閾値に入ります。

p95を使う理由は「平均は隠す、最大は誤魔化す」からです。平均は健全な大多数の呼び出しに引っ張られてスパイクを隠します。最大は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しています。一見致命的ですが、settings.json に "async": true を付けているため Claude Codeをブロックしません。非同期フラグが付いたhookは結果を待たずにセッションが開始します。問題はないが、asyncフラグがなければ起動のたびに45秒固まっていたはずです。

cost_guard.sh (p95: 2,518ms)：こちらは UserPromptSubmit の同期hookです。プロンプトを打つたびにccusageを呼んでプラン枠を確認しています。p95で2.5秒、最大5.8秒のブロックが毎ターン発生しています。感覚と一致します ―― プロンプトを送ってから応答が始まるまでの謎の2〜3秒の正体がこれでした。

obsidian_context.sh の平均が壊れている：meanが27,816ms（27秒！）なのにp95が782msという矛盾は、macのスリープ中にhookがゾンビとして生き残り、スリープ明けにまとめて記録されたレコードが混じっているためです。exitcodeが1になっているレコードも1件あり、スリープ明けの失敗と一致します。meanは使えません。p95が782msでasync: falseなので、SessionStart時に確かに待ちが入っていますが許容範囲です。

踏んだ落とし穴

  • $EPOCHREALTIME の小数点を除去するとき先頭ゼロが残る → sed 's/^0*//' を挟まないと整数変換でシェルがエラーになる
  • bash 4系（macOSのデフォルト /bin/bash）では $EPOCHREALTIME が空 → brew install bash で 5系を入れるか python3 フォールバックに任せる。フォールバックが効いているか echo "${BASH_VERSION}" で確認
  • asyncフラグ付きhookをラップしても計測できない → async: true のhookはClaude Codeが子プロセスとしてforkしたまま待たないため、elapsed_msはJSONLに正しく書かれる。ただしそのhookのブロック時間はゼロなので集計上⚠️が出ても運用上は無害
  • meanが壊れてもp95は正常 → スリープ中のゾンビレコードがmeanを押し上げても、p95は95パーセンタイル位置を動かすほどの量にはならない。meanを信じず常にp95を見る
  • exit codeを透過しないと事故る → ラッパーが常に exit 0 を返すと、pre_git_guard.sh がブロックしても通過してしまう。exit "$exit_code" で元のコードを返すのは必須
  • JSONLが5.8MBに育つ → 7日・29,866レコードでこのサイズ。ローテーションなしだと半年で100MB超になる。logrotateかlaunchdの定期trimが必要

まとめ

  • hook-latency-wrap.sh でhookをラップ → ~/.claude/logs/hook-latency.jsonl に実行時間を記録
  • hook-latency-report.sh でhook名ごとのcount/mean/p95/maxを集計、p95 > 1500ms で⚠️
  • 実測で判明したこと：skills-auto-update.sh は46秒かかるが async: true なのでブロックしない。cost_guard.sh はp95 2.5秒の同期ブロックが毎ターン発生していた
  • meanは外れ値（ゾンビプロセス・スリープ明け）で壊れる。p95が実体に近い
  • asyncフラグの有無がhookの「重さの意味」を変える。計測の前にasync/syncを確認する

次回は、このJSONLをもとに cost_guard.sh を非同期化した話 ―― 同期hookを非同期に切り替えるトレードオフと、非同期でも「ブロック前に必ず確認したいこと」をどう担保するかを書きます。

Lily（@bokuwalily）― 個人開発者。Claude Code で自動化基盤を組みながら、iOSアプリやWebサービスを量産しています

皆さんの ❤️ やシェアが励みになります！

0
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
0
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?