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?

⏱ フック遅延を計測してClaude Codeを速くする

0
Posted at

月商0円から半年でここまで来た手段の核心は、Claude Codeのフックを放置しないことです。


なぜこの仕組みが効くのか

Claude Codeには「フック」という仕組みがあります。ツール呼び出しの前後に任意のシェルスクリプトを差し込める、settings.json で配線するシンプルな機能です。わたし自身は今、PreToolUse・PostToolUse・Stop の三種類に十数本のフックを束ねていて、git の自動コミット・遅延レポート・セルフ監査・プロジェクト分類などを全部フック経由で動かしています。

問題は「フックは1セッション中に何十回も走る」という点です。

たとえばClaude Codeがファイルを10回Editするセッションがあるとします。PostToolUse フックがそのたびに起動すれば、フック1本の実行時間 × 10 が純粋な待機コストになります。ここに気づかず「なんかClaude Code重くなったな」と感じている人は多い。実際わたしも以前、セルフ監査フックにPython製の重い処理を仕込んでいた時期があって、体感でもっさりしていました。原因がわかるまでに数日かかりました。

体感の「重さ」はフックの本数ではなく、1本あたりの遅延に比例します。

フックが3本あっても全部50ms以下なら問題ない。フックが1本でもp95が2000msを超えていたら、10回呼ばれるだけで20秒の純粋な待ち時間が積み上がります。作業者は何もしていないのに20秒をロスしている。1日に複数セッションを回せば、意識しないうちに数分〜十数分を溶かしていることになります。

この損失は settings.json のフック欄を見ても気づけません。書いてあるのはコマンド文字列だけで、それが何ミリ秒かかっているかはどこにも記録されていないからです。だから計測が唯一の答えです。

ここで重要なのが「設定変更ゼロで始められる」という点です。後述する hook-latency-wrap.sh は既存のフックバイナリを引数に受けてラップするだけのシェルスクリプトです。元のフックの動作を一切変えずに、呼び出しごとの経過時間と終了コードをJSONL形式でログファイルに書き出します。計測を仕込むために本番フックのロジックを書き換える必要はありません。

「遅延はビジネス問題」という意識を持てるか

副業・個人開発で Claude Code を使っている人の多くは、フックを最初に動かすことに夢中になって計測まで手が回りません。わたしもそうでした。フックを追加するたびに「強化された」と感じて満足してしまう。でもそれは車にパーツを積みすぎて燃費が悪化しているのに「改造した」と喜んでいる状態に近い。

Claude Code は自律的に動くエージェントだからこそ、1セッションの密度が重要です。ユーザーが指示を出してから応答が返ってくるまでの時間は、フックの積み重ねで大きく変わります。わたしは「フック遅延の削減=自分の時給の向上」と考えています。月商120万という数字の裏には、使っているツールを可能な限り速くするという地味な習慣が積み上がっています。

bash の $EPOCHREALTIME という選択

今回紹介するラッパースクリプトは Python を使わず bash のビルトイン変数 $EPOCHREALTIME で計測しています。これは bash 5.0 以降で使える変数で、秒.マイクロ秒 形式(例:1720000000.123456)の現在時刻を返します。

なぜ Python を呼ばないのか。計測用スクリプトが自分で重くなっては本末転倒だからです。Python3 の起動コストは環境によって数十〜数百ミリ秒かかることがあります。計測のために毎回 Python を呼ぶと、計測値そのものにその起動コストが混入します。bash ビルトインなら追加のプロセス生成なしに現在時刻をマイクロ秒単位で取れます。

もっとも、bash が 5.0 未満の場合(古い macOS のデフォルトシェルなど)は $EPOCHREALTIME が空になります。その場合のフォールバックとして Python3 を呼ぶコードも実装に入っています。詳しくは次章のコード解説で触れます。


全体の流れ

システム全体の構成は次のとおりです。

settings.json
  └─ command: "hook-latency-wrap.sh  本来のhook.sh"
                        │
                        ├─ 本来の hook.sh を実行(動作は変わらない)
                        │
                        └─ 経過時間・終了コード を JSONL に追記
                                      │
                            ~/.claude/logs/hook-latency.jsonl
                                      │
                            hook-latency-report.sh [days]
                                      │
                              ターミナルに集計表を出力
                              (hook名・回数・mean・p95・max・fail)

ラッパーがJSONLに書き出し、レポーターがJSONLを読んで集計する。2スクリプト・1ログファイルの構成です。settings.json の変更は「コマンド文字列の先頭にラッパーのパスを足す」だけです。

hook-latency-wrap.sh の実装

全43行です。実際のコードをそのまま引用します。

#!/usr/bin/env bash
# hook-latency-wrap.sh — 任意の hook をラップして実行時間を JSONL に記録
#
# 使い方:
#   settings.json で command を以下に置き換える:
#     "command": "~/.claude/scripts/hook-latency-wrap.sh /path/to/hook.sh"
#
# 出力: ~/.claude/logs/hook-latency.jsonl  (1行 = 1呼び出し)
#   {"ts":"...","hook":"...","elapsed_ms":N,"exit_code":N}

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"

ポイントを三つ挙げます。

① タイムスタンプの取り方

$EPOCHREALTIME は 1720000000.123456 のような文字列を返します。これを ${EPOCHREALTIME//./} でドットを除去すると 1720000000123456(マイクロ秒単位の整数)になります。先頭のゼロは sed 's/^0*//' で削ります。開始時刻と終了時刻の差をマイクロ秒で取って1000で割ることでミリ秒の経過時間を得ています。外部コマンド date は終了時刻の記録(ts フィールド)にしか使っておらず、計測のクリティカルパスには置いていません。

② 本来のフックの終了コードを保持する

ラッパーの末尾が exit "$exit_code" になっているのは重要です。Claude Code はフックの終了コードを見てエラー判定します。ラッパーが常に0を返してしまうと、本来のフックが失敗してもClaude Codeに伝わらなくなります。この設計により、ラッパーを差し込んでもフックとしての動作は変わりません。

③ 追記モード(>>)で書く

>> "$JSONL" で追記しているので、複数のフックが同時に呼ばれてもファイルは壊れません。JSONL は1行1レコードの形式なので、追記が競合しても行単位で壊れるだけです。集計スクリプト側で try/except を使って壊れた行をスキップしているため、実運用上の問題はありません。

hook-latency-report.sh の実装

集計スクリプトも全体を引用します。

#!/usr/bin/env bash
# hook-latency-report.sh — hook-latency.jsonl を hook ごとに集計
# 使い方: ~/.claude/scripts/hook-latency-report.sh [days]
#   days=7 がデフォルト

set -uo pipefail
DAYS="${1:-7}"
JSONL="$HOME/.claude/logs/hook-latency.jsonl"
[ -f "$JSONL" ] || { echo "no data: $JSONL"; exit 0; }

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

if not stats:
    print(f"no records in last {days}d")
    sys.exit(0)

# 集計: count, mean, p95, max
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 降順(遅いものを上に)

print(f"=== hook latency (last {days}d, {total_records} records) ===")
print(f"{'hook':<32} {'n':>5} {'mean':>7} {'p95':>7} {'max':>7} {'fail':>5}")
print("-" * 70)
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

ヒアドック <<'PY' でPythonスクリプトをインライン定義しています。外部の .py ファイルに分けていないのは「2ファイル揃っていないと動かない」という依存を作りたくなかったからです。このスクリプト1本を持っていれば集計が完結します。

集計ロジックの核心は p95 = vals_sorted[min(n-1, int(n*0.95))] の1行です。ソート済みのリストから95パーセンタイルのインデックスを計算します。min(n-1, ...) はサンプル数が少ない場合の配列範囲外アクセスを防ぐガードです。出力は p95 降順にソートされるため、最も問題のあるフックが常に一番上に来ます。見た瞬間に何を直せばいいかわかります。

p95 が 1500ms を超えると行末に ⚠ が付きます。この閾値は「ツール呼び出し1回あたり1.5秒の純粋な待ちはさすがに許容できない」という判断で決めています。

出力の例はこうなります。

=== hook latency (last 7d, 843 records) ===
hook                              n    mean     p95     max  fail
----------------------------------------------------------------------
self_audit_stop.sh              127  1823ms  3240ms  8102ms     0 ⚠
pre_git_guard.sh                 98   420ms   890ms  2100ms     2
hook-latency-wrap.sh            618    12ms    18ms    45ms     0

この表を見ると「self_audit_stop.sh のp95が3240msで⚠が付いている、これが最優先の改善対象」とすぐわかります。meanが1823msなので平均でも1.8秒かかっている。127回呼ばれているから7日間で少なくとも 1823ms × 127 ≈ 3分54秒 を純粋な待機に使っていたことになります。計測して初めて見えてくる数字です。


実装の詳細

settings.json への配線

コード自体はここまで読んだとおりですが、実際に動かすには settings.json 側の書き方が鍵になります。たとえばこうなります。

{
  "hooks": {
    "PostToolUse": [
      {
        "matcher": "",
        "hooks": [
          {
            "type": "command",
            "command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/scripts/self_audit_stop.sh"
          }
        ]
      }
    ]
  }
}

command フィールドの先頭にラッパーのパスを置き、元のフックパスを第一引数として渡す形です。追加の引数がある場合は元フックのあとに書けば "$@" 経由でそのまま渡ります。変更するのはこの1行だけで、command の後ろに元コマンドを移動するだけです。

Claude Code がフックを呼び出すとき、stdin にツール呼び出しのコンテキストをJSON で流します。PostToolUse なら {"tool_name":"Edit","tool_input":{...},"tool_response":{...}} のような構造です。ラッパーが stdin を読まずに "$HOOK_BIN" "$@" で元フックをそのまま起動しているため、stdin は bash のプロセス継承で自動的に子プロセスへ引き継がれます。この部分は特別なコードを書く必要がなく、「何もしない」ことが正解です。

EPOCHREALTIME の文字列変換を追う

タイムスタンプ取得の行を改めて丁寧に読みます。

start_us=$(printf '%s' "${EPOCHREALTIME//./}" | sed 's/^0*//')

$EPOCHREALTIME は bash 5 以降で 1720543200.847231 のような文字列を返します。//./ でドットを全置換すると 1720543200847231 になります。これはマイクロ秒単位の UNIX タイムスタンプです。sed 's/^0*//' は先頭のゼロを除去しますが、実際にはUNIXタイムスタンプに先頭ゼロは付かないため、このsedはほぼ防御コードです。

終了後も同じ処理をして差を計算します。

elapsed_ms=$(( (end_us - start_us) / 1000 ))

マイクロ秒差を 1000 で割ると、ミリ秒になります。bash の整数演算 $(( )) は小数点以下を切り捨てるので、これで整数ミリ秒が得られます。

注意点は bash の整数は環境によって 32bit と 64bit が混在する ことです。1720543200847231 は十進数で 16桁弱。64bit整数(long long)は最大 9,223,372,036,854,775,807 なので余裕で収まります。macOS の bash 5 は 64bit ビルドなので問題ありません。ただし組み込みデバイスや古い 32bit Linux 環境で使う場合は計算がオーバーフローする可能性があります。そこまで気にする人は多くないと思いますが、「ログに負の elapsed_ms が記録されてレポートが壊れた」という問題が起きたときに原因として浮上することがあります(後述)。

report.sh のタイムゾーン問題

集計スクリプトの cutoff 計算を見ます。

cutoff = datetime.datetime.now() - datetime.timedelta(days=days)

そして wrap.sh でタイムスタンプを記録する際はこうなっています。

ts=$(date -u +%Y-%m-%dT%H:%M:%S)

-u フラグで UTC で記録しています。ところが Python 側の datetime.datetime.now() はローカル時刻を返します。日本標準時(JST)なら UTC+9 です。

これはズレを生みます。具体的に言うと、JST の朝 8:00 に hook-latency-report.sh 1 を実行するとローカル時刻の「24時間前(昨日朝8:00 JST)」が cutoff になります。しかしログの ts は UTC で記録されているため、昨日朝 8:00 JST = 昨日 23:00 UTC が cutoff です。つまり実際には「UTC 23:00より後のレコード」だけが拾われ、JST 換算で「今朝 8:00以降の9時間分しか見えない」ことになります。

日数が大きい(hook-latency-report.sh 7 など)場合は影響が相対的に小さいですが、1や2を指定したときは9時間分のズレが無視できなくなります。正確に直すなら cutoff を UTC で比較するべきで、datetime.datetime.utcnow() か datetime.datetime.now(datetime.timezone.utc) に変えるべきです。これは現行実装の既知のズレです。

fail カウンタの設計

エラー判定のコードは一見するとやや不思議な形をしています。

if r.get("exit_code", 0) not in (0, ):
    fail[r["hook"]] += 1

not in (0, ) とタプルで書いてあります。単なる != 0 でも同じ結果になりますが、タプルで書くことで「将来的に正常終了コードを増やしやすい」設計になっています。たとえば SIGINT で終了した場合(exit code 130)を正常扱いにしたければ not in (0, 130) と書けばいいだけです。今は (0, ) しか入っていませんが、このパターンは意図的な拡張点です。

また r.get("exit_code", 0) のデフォルト値がゼロになっているのは、exit_code フィールドが欠けたレコード(JSONLが途中で壊れた等)をエラーとして誤カウントしないためです。欠けているなら「成功として扱う」という保守的な設計です。


私が詰まった話

実装は小さいですが、実際に運用して数週間で5つの問題に当たりました。

① macOS のシステム bash が bash 3.2 でラッパー全体が即死した

最初につまずいたのがこれです。macOS はデフォルトの /bin/bash が 3.2 系です。Apple が GPLv3 を採用したくないため、2007 年より更新されていません。$EPOCHREALTIME は bash 5.0 で追加された変数なので、システム bash では未定義です。

set -uo pipefail が先頭に書いてあるため、未定義変数を参照した瞬間にシェルが終了コード 1 で即死します。

# bash 3.2 では EPOCHREALTIME が unbound variable → ここで死ぬ
start_us=$(printf '%s' "${EPOCHREALTIME//./}" | sed 's/^0*//')

症状としては「フックが動いている気配がない」でした。ログファイルが空のまま、でもエラーも見えない。Claude Code がフックのエラー出力を静かに捨てていたため、何が起きているかわかりませんでした。

直接シェルで試して初めて気づきました。

$ /bin/bash --version
GNU bash, version 3.2.57(1)-release

$ /bin/bash ~/.claude/scripts/hook-latency-wrap.sh ~/.claude/scripts/self_audit_stop.sh
/bin/bash: EPOCHREALTIME: unbound variable

直し方は brew install bash で bash 5.x を入れて #!/usr/bin/env bash が Homebrew の bash を参照するよう PATH を設定することです。あるいはスクリプト先頭を #!/opt/homebrew/bin/bash に明示する方法もありますが、移植性が落ちるため前者を選びました。

フォールバックが用意されているのに機能していなかったのは、フォールバックに辿り着く前に set -u で死んでいたからです。

② stdin を安全にしようとして逆に壊した

Claude Code がフックに stdin 経由で JSON を流すと知ったとき、「ラッパーが stdin を読み取ってしまったら元フックに渡らなくなるのでは」と心配しました。安全のため、一度 stdin を受け取って再度パイプに流す書き方を試みました。

# やってしまったNG実装
input=$(cat)
echo "$input" | "$HOOK_BIN" "$@"

これは2重に間違っていました。まず cat で全 stdin を読み切ってから変数に入れるため、元フックが stdin を非同期・ストリーミングで読む実装だった場合に競合が起きます。次に echo でパイプ経由で渡すと、stdin がパイプに変わるため、フック側が stdin を tty と期待しているケースで壊れます。

実際には bash でコマンドを実行すると stdin はそのまま子プロセスへ引き継がれます。"$HOOK_BIN" "$@" だけで stdin は流れます。「何もしない」が正解でした。元に戻したら動きました。

③ hook 名が衝突して集計がおかしかった

hook_name=$(basename "$HOOK_BIN") は ファイル名だけ を取得します。異なるプロジェクトで同名のフックを使っていると、集計上は同一フックとして扱われます。

わたしは pre_git_guard.sh をグローバル設定とある個人プロジェクトの両方に置いていました。レポートを見たとき、pre_git_guard.sh の呼び出し回数がどう考えても多く、p95 が想定より高い数値でした。

hook                              n    mean     p95
pre_git_guard.sh               312   198ms   940ms

実際はグローバル版(高速)とプロジェクト版(Gitリモートをチェックする重い処理)の合算だったため、p95 が引き上げられていました。見た目は「pre_git_guard.sh が遅い」ですが、実際は一方だけが遅い状態です。

対策としてログのフィールドにフルパスを追記しました。

hook_name=$(basename "$HOOK_BIN")
hook_path="$HOOK_BIN"   # フルパスも記録

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

report.sh 側では hook ではなく path で group by するよう変更しました。これで異なるパスの同名フックが分離されて見えるようになります。

④ ラッパーを二重に設定してしまった

グローバルの ~/.claude/settings.json とプロジェクトの .claude/settings.json を両方管理していて、あるとき settings を統合した際に既にラッパーが掛かっているフックにさらにラッパーを設定しました。

"command": "~/.claude/scripts/hook-latency-wrap.sh ~/.claude/scripts/hook-latency-wrap.sh ~/.claude/scripts/self_audit_stop.sh"

症状は「レポートの n が2倍になっている」「hook-latency-wrap.sh 自体がレポートに現れる」でした。ラッパーが自分自身の実行時間を記録するため、外側のラッパーが hook-latency-wrap.sh という hook名でJSONLに追記するのです。

hook                              n    mean     p95
hook-latency-wrap.sh            843     8ms    14ms   ← これが出たら二重ラップ
self_audit_stop.sh              843  1923ms  3890ms

hook-latency-wrap.sh がレポートに登場したら即座に二重ラップを疑うことにしています。確認コマンドは次のとおりです。

grep -r "hook-latency-wrap" ~/.claude/settings*.json .claude/settings*.json 2>/dev/null

パスがネストして登場した行を見つければ該当箇所です。

⑤ elapsed_ms が負の値になってレポートが崩れた

一度だけ、レポートの mean が -1ms と表示されたことがあります。JSONL を開いて確認すると、数行 "elapsed_ms":-7 のようなレコードが混じっていました。

原因は bash の整数演算の桁あふれ ではなく、$EPOCHREALTIME の精度の問題でした。フックが非常に速く(1ms未満)終了した場合、start_us と end_us が完全に一致して差がゼロになることはあります。しかしマイナスになるのはおかしい。

実際に調べると、同じ bash セッション内で $EPOCHREALTIME の値が稀に「逆転」することがあります。これは macOS のシステムクロックが NTP 補正で微調整されたタイミングと、bash 変数の更新タイミングが重なったときに起きます。1マイクロ秒単位の話なので通常は気にならないのですが、頻繁に NTP 補正が入る環境(仮想マシン等)では発生率が上がります。

対処は report.sh 側で elapsed_ms < 0 のレコードを捨てることです。

if r.get("elapsed_ms", 0) < 0:
    continue

これを入れてからは集計値が安定しています。元の実装にはこのガードが入っていないので、もし負の値が出たら追加することをおすすめします。

つまずきポイント

前段の「私が詰まった話」で取り上げた 5 つ(bash 3.2 での即死・stdin ラップ・basename 衝突・二重ラップ・負の elapsed_ms)以外にも、運用を続ける中で詰まったポイントがいくつかあります。同じところで止まらないよう、網羅的にまとめます。

  • chmod +x 忘れで "Permission denied" のまま無音終了する。Claude Code はフックのエラー出力を表示しないため、ラッパーがそもそも起動していないのか・フックが失敗しているのかの区別がつきません。JSONL が空のとき、最初に確認すべきはパーミッションです。ls -la ~/.claude/scripts/hook-latency-wrap.sh で -rwxr-xr-x の x が付いているか確認します。wrap.sh・元フック双方の実行ビットが必要です。

  • settings.json でのチルダ ~ 展開に依存しない。"command": "~/.claude/scripts/hook-latency-wrap.sh ..." と書いた場合、Claude Code の実装がシェルを介さずに execv に渡すパスでチルダを展開しないことがあります。動いているように見えてもセッション再起動後に壊れるケースがあります。安全策は $HOME/.claude/scripts/hook-latency-wrap.sh のように $HOME を使うか、絶対パスで書くことです。

  • launchd や cron 経由で report.sh を定期実行するとき PATH が足りない。~/.zshrc で設定した Homebrew の PATH(/opt/homebrew/bin)はインタラクティブシェルでしか読まれません。launchd の EnvironmentVariables を明示しないと python3 が見つからず、report.sh がサイレント失敗します。plist に <key>PATH</key><string>/opt/homebrew/bin:/usr/bin:/bin</string> を書くか、スクリプト冒頭で export PATH="/opt/homebrew/bin:$PATH" するのが確実です。

  • macOS Ventura 以降で python3 が未インストールだとフォールバックも死ぬ。macOS Ventura 以降、Xcode Command Line Tools を入れていない環境では python3 コマンドが存在しません。wrap.sh の $EPOCHREALTIME フォールバック(bash < 5 向け)が python3 を呼ぶため、フォールバック先も同時に死にます。brew install python するか、Homebrew の bash 5 を使うことで根本解決します。どちらの手段もひとつのコマンドで終わります。

  • JSONL が無限に肥大化する。hook-latency.jsonl への追記は止まる仕組みがなく、何ヶ月も運用すると数万行を超えます。report.sh は全行をパースしてから期間フィルタするため、10 万行を超えると起動時間が数百ミリ秒かかり始める環境がありました。月次で圧縮ローテーションする 1 行の launchd エントリを最初から仕込んでおくのが安全です。

# 月次実行(launchd StartCalendarInterval)
gzip -c ~/.claude/logs/hook-latency.jsonl \
  > ~/.claude/logs/hook-latency-$(date +%Y%m).jsonl.gz \
  && : > ~/.claude/logs/hook-latency.jsonl
  • days 引数を省略して 7 日固定のまま使い続ける。導入直後はデータが 1 日分しか溜まっていないため、hook-latency-report.sh の days=7 デフォルトだと「n が 10 件以下で p95 が信頼できない」状態になります。最初の 1 週間は hook-latency-report.sh 1 で当日分を見て、1 週間後に hook-latency-report.sh 7 に切り替えるのが安定した使い方です。

  • ラッパーを入れたら重くなったと感じてラッパーを疑う。体感の重さはラッパー以前からあったフックの遅延が「計測によって初めて見えるようになった」だけです。wrap.sh 自体のオーバーヘッドは実測で mean 12ms・p95 18ms 程度(前段の出力例で hook-latency-wrap.sh 行を参照)。この値を超える遅延は元フックのコストです。ラッパーを外して「速くなった」と感じるのは計測が消えた錯覚です。

  • フック名にパイプ記号や引用符が含まれると JSONL が壊れる。hook_name=$(basename "$HOOK_BIN") はファイル名をそのまま JSON 文字列フィールドに埋め込みます。スクリプト名に " や \ が入ると JSON が破損し、report.sh の try/except に吸収されて黙ってカウントが減ります。フック名は英数字・アンダースコア・ハイフンだけに統一しておくのが最も安全です。

  • 複数の Claude Code セッションが同時に動いていて集計が混在する。デスクトップアプリとターミナル CLI を同時に動かすと、JSONL には両セッションのログが混入します。「あのセッションで改善したはずなのに p95 が変わらない」という現象が起きたら別セッション混入を疑います。JSONL に session_id を追記したい場合、CLAUDE_SESSION_ID 環境変数の存在を確認するのが最初のステップです(2026 年 7 月時点では環境変数として公開されていないため、プロセス ID で代替する方法が現実的です)。

  • report.sh の cutoff がローカル時刻、ログが UTC という 9 時間ズレを見落とす。前段で詳述しましたが、-u フラグつきで UTC 記録されたログと、datetime.datetime.now() で取るローカル時刻(JST)の cutoff がズレます。hook-latency-report.sh 1 と指定したとき、朝 8 時に実行すると「今朝 8 時以降の 0 時間分」しか見えない極端な事態が起きることがあります。JST 環境では days=1 や days=2 を指定したときに件数が異様に少なければこのズレが原因です。


ベストプラクティス

運用を続けた結果、「最初からこうしておけばよかった」と感じる項目を 12 個まとめます。

① 計測から始めて最適化は後

フックを追加するたびに「強化した」と感じがちですが、数値なしの改善はプラセボです。hook-latency-wrap.sh を仕込んで 1 週間データを溜めてから改善に入る順番を守ります。数値が先、直感は後。

② 改善指標は mean ではなく p95 にする

フック遅延は均一ではありません。ほとんどのケースで 200ms 以内に終わっても、Git リモートのタイムアウトが踏まれた瞬間に 5000ms を記録します。そのスパイクが体感の「重さ」の正体です。p95 を見ることで「95 回に 5 回は許容外の遅延がある」という実態が掴めます。mean を下げることに集中しても体感が変わらないのはこれが理由です。

③ p95 > 1500ms のフックは削除前に原因を特定する

⚠ が出たフックをすぐ削除しようとしないことが大事です。重さの原因がネットワーク I/O(Git リモート)なのか・CPU(Python 処理)なのか・シェル起動コスト(サブシェルの多用)なのかで対策が全く違います。まず time ~/.claude/scripts/slow_hook.sh < /dev/null で単体実行して原因を切り分けます。

④ ラッパー自体のオーバーヘッドを定数として把握しておく

わたしの環境では wrap.sh 自体のオーバーヘッドは mean 12ms・p95 18ms でした(前段の出力例で hook-latency-wrap.sh 行を参照)。フックの改善目標を設定するときはこの固定コストを差し引いた値を「本来のフックのコスト」として扱います。

⑤ シェバンを #!/usr/bin/env bash にして Homebrew bash を通す

#!/bin/bash はシステム bash(macOS では 3.2)に直結します。#!/usr/bin/env bash にしておけば PATH に入っている bash が使われます。brew install bash で bash 5.x を入れて PATH を通せば、bash 3.2 起因の問題がまとめて消えます。

⑥ settings.json のコマンドはフルパスで書く

チルダ表記はシェル経由で呼ばれる場合は展開されますが、Claude Code の実装依存です。$HOME/.claude/scripts/hook-latency-wrap.sh か絶対パスで書いておくと、将来 Claude Code の内部実装が変わっても影響を受けません。

⑦ JSONL ローテーションを最初に仕込む

後から入れると既存のログが重くなってから気づきます。最初に設定します。圧縮 + truncate の 2 コマンドで済むので launchd の月次 StartCalendarInterval に入れておくだけです。

⑧ elapsed_ms < 0 のガードを report.sh に追記する

現行実装には含まれていません(前段の report.sh ソース参照)。NTP 補正タイミングで稀に負値が記録されると mean がマイナスになってレポートが崩れます。try/except ブロック内の先頭に 1 行追加するだけです。

# with open(log) as f: ループ内、json.loads 直後に追記
if r.get("elapsed_ms", 0) < 0:
    continue

⑨ プロジェクト固有フックには prefix をつける

pre_check.sh のような汎用名を複数プロジェクトで使うと basename での集計が混じります。proj-foo_pre_check.sh のようにプロジェクト prefix をつけると、集計表で一目でどのプロジェクトの何かがわかります。既存フックのリネームは ln -s でエイリアスを作れば実体を変えずに移行できます。

⑩ report.sh を定期実行して変化を記録する

手動で実行するのを忘れがちです。わたしは launchd で毎週月曜 9:00 に実行して terminal-notifier 経由で通知を受け取っています。「今週の p95 が先週より 300ms 悪化」という変化を見逃さないためです。数値は記録されてこそ意味を持ちます。

⑪ フックを増やす前に既存フックの p95 合計を確認するルールを持つ

わたしは「新しいフックを追加する前に report.sh を見て、既存フックの合計 p95 時間が 3000ms 以下であること」を条件にしています。超えていたら増やす前に削る。このルールがなければフックは際限なく増えます。PostToolUse フックは 1 セッションで数十回呼ばれます。

⑫ 閾値 1500ms を自分の環境に合わせてカスタマイズする

p95 > 1500ms で ⚠ が出る設計ですが、Git リモートチェックを含むフックなら 2000ms が常態でも許容できるケースがあります。逆に、100ms に収めたいフックなら 500ms で警告したい。report.sh の flag = " ⚠" if p95 > 1500 else "" の 1500 を環境変数化しておくと、HOOK_WARN_MS=500 hook-latency-report.sh 7 のように呼び出し時に動的に変えられます。


まとめ

Claude Code のフックは「動けばいい」という設計ではなく、「速く動く」ことが直接生産性に効く設計です。1 本のフックが 2000ms かかっていて、1 セッション中に 50 回呼ばれれば、1 分 40 秒をエージェントの応答待ちではなくフックの待機に使っていることになります。気づかなければずっと続きます。

hook-latency-wrap.sh(43 行)と hook-latency-report.sh(53 行)の 2 本で、フックごとの p95・mean・max・エラー率が可視化できます。前段で見たとおり、self_audit_stop.sh の p95 が 3240ms で 127 回呼ばれていたケースでは、7 日間に 3 分 54 秒 の純粋な待機があったことが初めてわかりました。計測する前は「重いかな」という感覚しかなく、改善の優先度を付けられない状態でした。

settings.json の command フィールドの先頭にラッパーのパスを追記するだけで始められます。今夜入れれば明日の朝には 1 日分のデータが溜まっています。

月商 120 万という数字は、ひとつひとつの「体感の重さ」を測定可能な問題に変換して潰してきた積み重ねです。毎日使うツールを 20 秒速くすれば 1 年で 2 時間以上が返ってきます。その時間に次の仕組みを作れます。


仕組みの全体像・月120万の内訳・30日手順は有料noteにまとめています。
📕 Claude Code自律環境で、実際どう稼ぐか ― 仕組み・実例・始め方・サポート


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
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?