Show original
Enjoyed this article?
Support Lily
Share
⌛️Identify the cause of slow Claude Code hooks
AI translation
― wrap 1行でp95を計測
About 21 min read129
AI translation
― wrap 1行でp95を計測
Enjoyed this article?
Support Lily
Following the previous work プロジェクト台帳とsymlinkツリーの話, this is part of the Claude Code environment series.
As you add more hooks, you start to feel "something got slower." There are mysterious gaps between turns, and it takes a long time from typing a prompt to when the response starts. But "which hook is causing it" is hard to pinpoint. Hooks are called from inside Claude Code, and if there's no error, nothing gets logged. In this article, I'll introduce a single wrapper that writes hook execution times to JSONL, and a script to aggregate them. I'll also show all the actual measurements.
My Claude Code environment currently has 10+ types of hooks installed.
UserPromptSubmit: Cost guard, model routing notification, context loadingPreToolUse(Edit|Write): Secret scanning, .env protectionPreToolUse(Bash): Git command guardSessionStart: Skill auto-update, Obsidian context loadingMessageDisplay: FilteringWhen hooks run synchronously, Claude Code blocks until they complete. There's no way to manually track whether "cost_guard.sh is slow every time" or "it's obsidian_context.sh instead."
~/.claude/scripts/hook-latency-wrap.sh is the actual wrapper implementation.
#!/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"There are two key design points.
① Don't call python in $EPOCHREALTIME. date +%s%N only runs on Linux, and macOS's date doesn't support nanoseconds. The bash 5+ built-in variable $EPOCHREALTIME returns seconds + microseconds in 1716912345.678901 format. On macOS Ventura and later, /bin/bash --version is 5.x, so it's available by default.
② Transparently pass through the original exit code in exit "$exit_code". If a hook returns exit 2, Claude Code should block and show an error, but if the wrapper always returns 0, that information disappears. Since this is a measurement-only wrapper, I don't modify the hook's behavior at all.
Just pass the existing hook command directly to the wrapper. Don't change the surrounding structure.
// 変更前
{
"type": "command",
"command": "~/.claude/hooks/cost_guard.sh"
}
// 変更後（1行変えるだけ）
{
"type": "command",
"command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/hooks/cost_guard.sh"
}The relevant part of the actual ~/.claude/settings.json looks like this. All 3 hooks plugged into UserPromptSubmit are wrapped.
"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"
}
]
}
]This appends one line to ~/.claude/logs/hook-latency.jsonl for each hook invocation.
{"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}~/.claude/scripts/hook-latency-report.sh [days] produces the aggregation. The default is the last 7 days.
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}")
PYThe decision criterion is: if p95 exceeds 1,500ms, display ⚠. Synchronous hooks in Claude Code block the user for exactly this duration. If you have to wait 1.5 seconds every time you send a prompt, it crosses the threshold where you feel "slow."
:::message The reason for using p95 is "the average hides spikes, the maximum lies." The average gets pulled by the healthy majority of calls and hides spikes. The maximum jumps on a single outlier (post-sleep, timeout, zombie process) and diverges from daily experience. p95 means "95 out of 100 calls are within this time," so it honestly shows daily slowness. :::
=== 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 0Two have ⚠️ flags, but the underlying issues are different.
skills-auto-update.sh (p95: 46 seconds): Every SessionStart, it takes 45 seconds to git pull the skill list. It looks fatal at first glance, but settings.json has "async": true attached, so it doesn't block Claude Code. Hooks with the async flag start the session without waiting for results. No problem, but without the async flag, startup would freeze for 45 seconds every time.
cost_guard.sh (p95: 2,518ms): This is a synchronous hook in UserPromptSubmit. It calls ccusage every prompt to check the plan quota. p95 is 2.5 seconds, with maximum 5.8-second blocks occurring every turn. This matches the feeling ―― the mysterious 2-3 second gap from sending a prompt to when the response starts was this.
obsidian_context.sh has broken mean: The contradiction of mean being 27,816ms (27 seconds!) while p95 is 782ms is because the hook survived as a zombie during Mac sleep and records got batched when the Mac woke up. There's also one record with exit code 1, matching the post-sleep failure. Mean is unusable. p95 is 782ms, so async: false, and there is indeed a wait at SessionStart, but it's within tolerance.
$EPOCHREALTIME → Need to insert sed 's/^0*//' or the shell errors on integer conversion/bin/bash), $EPOCHREALTIME is empty → Either install 5.x with brew install bash or fall back to python3. Verify the fallback is working with echo "${BASH_VERSION}"async: true hooks are forked by Claude Code without waiting, so elapsed_ms is correctly written to JSONL. But since that hook's block time is zero, even if ⚠️ appears in aggregation, it's harmless operationallyexit 0, even if pre_git_guard.sh blocks, it passes through. Returning the original code with exit "$exit_code" is essentialhook-latency-wrap.sh → Record execution time to ~/.claude/logs/hook-latency.jsonlhook-latency-report.sh, show ⚠️ when p95 > 1500msskills-auto-update.sh takes 46 seconds but async: true so doesn't block. cost_guard.sh had p95 2.5-second synchronous blocks happening every turnNext time, based on this JSONL, the story of making cost_guard.sh asynchronous ―― the tradeoffs of switching synchronous hooks to async, and how to guarantee "things we must always check before blocking" even asynchronously.
Lily (@bokuwalily) ― Individual developer. Building automation infrastructure with Claude Code while mass-producing iOS apps and web services
◼︎ Apps I've made are summarized at **ポートフォリオ**📱
◼︎ New releases and development behind-the-scenes shared on X **@bokuwalily**🐦
◼︎ OSS: **github.com/bokuwalily**🐙
Your ❤️ and shares are my motivation!
前作の プロジェクト台帳とsymlinkツリーの話 に続く、Claude Code環境シリーズです。
hookを増やしていくと「なんか重くなった」という感覚が出てきます。ターンとターンの間に謎の間がある、プロンプトを打ってから応答が始まるまでが長い。でも「どのhookが原因か」を突き止めるのが難しい。hookはClaude Codeの内部から呼ばれ、エラーでなければ何もログに出ないからです。この記事では、hookの実行時間をJSONLに書き出すラッパー1本と、それを集計するスクリプトを紹介します。実測値も全部出します。
私のClaude Code環境には現時点で10種類以上のhookが刺さっています。
UserPromptSubmit: コストガード・モデルルーティング通知・コンテキスト読み込みPreToolUse(Edit|Write): シークレットスキャン・.env保護PreToolUse(Bash): gitコマンドガードSessionStart: スキル自動更新・Obsidian文脈読み込みMessageDisplay: フィルタリングhookが同期実行の場合、完了するまでClaude Codeはブロックします。「cost_guard.sh が毎回重いのか」「それとも obsidian_context.sh か」を手で追うのは無理です。
~/.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本体の動作には一切手を加えません。
既存の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}~/.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}")
PYp95が 1,500ms を超えたら ⚠ を表示するのが判断基準です。Claude Codeの同期hookはこの時間だけユーザーをブロックします。プロンプトを打つたびに1.5秒待たされると、体感として「重い」と感じる閾値に入ります。
:::message p95を使う理由は「平均は隠す、最大は誤魔化す」からです。平均は健全な大多数の呼び出しに引っ張られてスパイクを隠します。最大は1回の外れ値（スリープ明け・タイムアウト・ゾンビプロセス）で跳ね上がり、日常の体感と乖離します。p95は「100回に95回がこの時間以内」なので、日常の遅さを正直に示します。 :::
=== 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*//' を挟まないと整数変換でシェルがエラーになる/bin/bash）では $EPOCHREALTIME が空 → brew install bash で 5系を入れるか python3 フォールバックに任せる。フォールバックが効いているか echo "${BASH_VERSION}" で確認async: true のhookはClaude Codeが子プロセスとしてforkしたまま待たないため、elapsed_msはJSONLに正しく書かれる。ただしそのhookのブロック時間はゼロなので集計上⚠️が出ても運用上は無害exit 0 を返すと、pre_git_guard.sh がブロックしても通過してしまう。exit "$exit_code" で元のコードを返すのは必須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秒の同期ブロックが毎ターン発生していた次回は、このJSONLをもとに cost_guard.sh を非同期化した話 ―― 同期hookを非同期に切り替えるトレードオフと、非同期でも「ブロック前に必ず確認したいこと」をどう担保するかを書きます。
Lily（@bokuwalily）― 個人開発者。Claude Code で自動化基盤を組みながら、iOSアプリやWebサービスを量産しています
◼︎作ったアプリは **ポートフォリオ** にまとめています📱
◼︎新着・開発の裏側は X **@bokuwalily** で発信しています🐦
◼︎OSS: **github.com/bokuwalily**🐙
皆さんの ❤️ やシェアが励みになります！