DEV Community

Lily
Lily

Posted on • Originally published at dev.to

Find Out Which Claude Code Hook Is Slow — Measure p95 With a One-Line Wrapper

#claudecode #automation #shellscript #bash

This is another entry in my Claude Code environment series, following the previous piece on the project ledger and symlink tree.

As you add more hooks, a vague feeling creeps in: "things got heavier." There's a mysterious pause between turns, and a long gap between hitting enter on a prompt and the response starting. But pinning down which hook is responsible is hard. Hooks are called from inside Claude Code, and unless they error, nothing shows up in any log. In this article I introduce a single wrapper that writes each hook's execution time to a JSONL file, plus a script to aggregate it. I'll show all the real numbers too.

The problem: I can tell hooks are slow, but not which one

My Claude Code environment currently has more than 10 kinds of hooks wired in.

  • UserPromptSubmit: cost guard, model routing notification, context loading
  • PreToolUse(Edit|Write): secret scan, .env protection
  • PreToolUse(Bash): git command guard
  • SessionStart: automatic skill update, Obsidian context loading
  • MessageDisplay: filtering

When a hook runs synchronously, Claude Code blocks until it finishes. Manually tracing whether "cost_guard.sh is heavy every time" or "it's actually obsidian_context.sh" is impossible.

How the measurement works: a single $EPOCHREALTIME wrapper

~/.claude/scripts/hook-latency-wrap.sh is the wrapper itself.

#!/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"
Enter fullscreen mode Exit fullscreen mode

There are two key design points.

① Don't call python — use $EPOCHREALTIME. date +%s%N only works on Linux, and macOS's date doesn't support nanoseconds. The built-in variable $EPOCHREALTIME in bash 5 and later returns seconds plus microseconds in the form 1716912345.678901. On macOS Ventura and later, /bin/bash --version is 5.x, so it's usable out of the box.

② Pass through the original exit code with exit "$exit_code". If a hook returns exit 2, Claude Code is supposed to block and show an error, but if the wrapper always returns 0, that information is lost. Since this is a measurement-only wrapper, it makes no changes whatsoever to the hook's own behavior.

How to slot it into settings.json

You just pass the existing hook command through the wrapper. The surrounding structure stays the same.

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

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

The relevant part of my actual ~/.claude/settings.json looks like this. All three hooks wired 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"
      }
    ]
  }
]
Enter fullscreen mode Exit fullscreen mode

With this, every hook call is appended, one line at a time, to ~/.claude/logs/hook-latency.jsonl.

{"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}
Enter fullscreen mode Exit fullscreen mode

Aggregation script: hook-latency-report.sh

~/.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}")
PY
Enter fullscreen mode Exit fullscreen mode

The decision criterion is to display ⚠ when p95 exceeds 1,500ms. A synchronous Claude Code hook blocks the user for exactly this long. When you're kept waiting 1.5 seconds every time you send a prompt, you're into the range where it perceptibly feels "heavy."

Note
The reason to use p95 is that "the mean hides, the max deceives." The mean gets pulled down by the healthy majority of calls and hides the spikes. The max shoots up from a single outlier (waking from sleep, a timeout, a zombie process) and diverges from the everyday experience. p95 means "95 out of 100 calls fall within this time," so it honestly shows the everyday slowness.

Real numbers: results from 29,866 records over the last 7 days 

=== 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
Enter fullscreen mode Exit fullscreen mode

Two hooks have the ⚠ raised. Their actual situations are different.

skills-auto-update.sh (p95: 46 seconds): On SessionStart it spends 45 seconds every time doing a git pull of the skill list. At a glance this looks fatal, but because I've set "async": true in settings.json, it does not block Claude Code. A hook with the async flag lets the session start without waiting for the result. There's no problem, but without the async flag it would have frozen for 45 seconds on every startup.

cost_guard.sh (p95: 2,518ms): This one is a synchronous UserPromptSubmit hook. Every time you enter a prompt, it calls ccusage to check the plan quota. A block of 2.5 seconds at p95, up to 5.8 seconds at max, happens on every turn. It matches the feeling — the mysterious 2 to 3 seconds between sending a prompt and the response starting was this all along.

obsidian_context.sh's mean is broken: The contradiction of a mean of 27,816ms (27 seconds!) while the p95 is 782ms is because records where the hook survived as a zombie during a Mac sleep, then got recorded all at once after waking, are mixed in. There's also one record with exit code 1, which matches a post-sleep failure. The mean is unusable. The p95 is 782ms with async: false, so there is indeed a wait at SessionStart, but it's within acceptable range.

Pitfalls I hit

  • When stripping the decimal point out of $EPOCHREALTIME, leading zeros remain → without inserting sed 's/^0*//', the shell errors on the integer conversion
  • On bash 4.x (macOS's default /bin/bash), $EPOCHREALTIME is empty → either install bash 5 with brew install bash or leave it to the python3 fallback. Check whether the fallback is kicking in with echo "${BASH_VERSION}"
  • You can't measure a hook wrapped with the async flag → an async: true hook is forked by Claude Code as a child process that it never waits for, so elapsed_ms is still written correctly to the JSONL. However, that hook's block time is zero, so even if a ⚠ shows up in the aggregation, it's harmless operationally
  • Even when the mean is broken, p95 is fine → even if zombie records during sleep push the mean up, they aren't a large enough quantity to move the 95th-percentile position. Don't trust the mean; always look at p95
  • You'll have an accident if you don't pass through the exit code → if the wrapper always returns exit 0, then even when pre_git_guard.sh blocks, it slips through. Returning the original code with exit "$exit_code" is mandatory
  • The JSONL grows to 5.8MB → that's the size for 7 days and 29,866 records. Without rotation it goes over 100MB in half a year. You need logrotate or a periodic launchd trim

Summary

  • Wrap hooks with hook-latency-wrap.sh → the execution time is recorded to ~/.claude/logs/hook-latency.jsonl
  • Aggregate count/mean/p95/max per hook name with hook-latency-report.sh, with ⚠ for p95 > 1500ms
  • What the real numbers revealed: skills-auto-update.sh takes 46 seconds but is async: true so it doesn't block. cost_guard.sh was causing a synchronous block of p95 2.5 seconds on every turn
  • The mean gets broken by outliers (zombie processes, waking from sleep). p95 is closer to reality
  • The presence or absence of the async flag changes what a hook's "heaviness" even means. Check async/sync before measuring

Next time I'll write about making cost_guard.sh asynchronous based on this JSONL — the trade-offs of switching a synchronous hook to asynchronous, and how to guarantee the things you "always want to check before blocking" even when it's asynchronous.

Written by **Lily* — I ship iOS apps and automate my content stack with Claude Code.
Follow along: Portfolio · X · GitHub*

Top comments (0)