12 Pitfalls I Hit Auto-Logging Claude Code Subagents with a Stop Hook (and How the Numbers Cut My Weekly Cost 15–20%)

I had a gut feeling that my general-purpose subagent was the slow one. Then I measured it: 18 seconds on average, faster than Explore at 22. The real drag was code-reviewer at 37 seconds. Changing one habit based on that number dropped my weekly Claude Code spend by roughly 15–20%. I made a couple hundred thousand yen a month as a student juggling side gigs, got laid off and went back to zero, and spent six months building an autonomous Claude Code setup that now runs at about ¥1.2M in monthly revenue. The foundation of that setup is post-session log collection driven by a Stop hook. This post covers the implementation, the 12 pitfalls I hit along the way, and the jq recipes I use every week. Why this works After using Claude Code for a while, a nagging feeling sets in: "I have no idea where the cost is going." You mix Explore agents, code-reviewer agents, general-purpose agents, and before you know it a session has been running for tens of minutes. But which agent is slow? Which one errors most often? I had never seen a number. Saying "that agent feels heavy" is not data. Without data, you can't tell what to fix. For someone shipping systems solo at volume, that's a fatal blind spot. Optimizing a workflow starts with measuring it. Claude Code ships with a mechanism that lets you automate that measurement: the Stop hook. A Stop hook is a shell script that runs every time a Claude Code session ends. The hook receives a transcript_path — the path to the raw JSONL conversation log for the entire session, including tool calls, agent launches, and response timestamps. In other words, every time a session ends, you automatically get a chance to read "everything that happened in this session." Once I noticed that, my thinking changed. There's no need to keep records by hand. Trigger a script on session end, parse transcript_path, and write a list of subagent invocations out to JSONL. That alone accumulates "which agent took how many seconds, and did it succeed or fail." Then aggregate the ledger with jq, and you move from gut feelings to a conversation about numbers. One more important point: this approach touches nothing in Claude Code itself. A Stop hook is enabled by adding a single line to ~/.claude/settings.json. It doesn't change the original behavior; it just piggybacks on an existing event, session end. Near-zero side effects is a big advantage when you're maintaining a high-volume environment. What's inside transcript.jsonl Of the JSON the Stop hook receives, two fields matter. { "session_id": "...", "transcript_path": "/path/to/transcript.jsonl" } The file at transcript_path contains every message exchanged in the session in JSONL format (one JSON object per line). Inside each line's message.content, you'll find "type": "tool_use" blocks representing tool calls. Subagent launches are recorded here as "name": "Agent". Note that even though Claude Code's UI displays "Task", the tool name in the transcript is "Agent" (the script's comment spells this out: "In Claude Code transcripts, the 'Task' tool is recorded as name="Agent""). The subagent_type lives in input.subagent_type. The result of an agent call appears on a separate line as "type": "tool_result", linked to the call via tool_use_id. If is_error: true is present, it ended in error; otherwise, it succeeded. Once you understand this structure, a two-pass Python script is all it takes to extract subagent execution records. Overall flow Here's the whole system as a diagram. Claude Codeセッション ┌─────────────────────────────────────────────────┐ │ tool_use (name="Agent", subagent_type="Explore") │ │ ...処理中... │ │ tool_result (tool_use_id=xxx, is_error=false) │ └─────────────────────────────────────────────────┘ ↓ セッション終了 (Stop イベント) ┌─────────────────────────────────────────────────┐ │ Stop hook: stop_agent_tracker.sh │ │ stdin: {"session_id", "transcript_path", ...} │ └─────────────────────────────────────────────────┘ ↓ transcript_path を読み込む ┌─────────────────────────────────────────────────┐ │ Python: 2パス解析 │ │ Pass1: uses{} / results{} を構築 │ │ Pass2: tool_use_id で突き合わせ・duration算出 │ └─────────────────────────────────────────────────┘ ↓ 追記 ~/.claude/logs/agent-invocations.jsonl When the Stop hook fires, it receives JSON on stdin, and a Python script reads the transcript using the transcript_path inside it. The output destination is fixed: ~/.claude/logs/agent-invocations.jsonl. Inside stop_agent_tracker.sh The script is almost entirely Python. The shell portion only handles passing environment variables. INPUT=$(cat) # stdin から Stop イベント JSON を受け取る export STOP_INPUT="$INPUT" export OUT_LOG_PATH="$OUT_LOG" # ~/.claude/logs/agent-invocations.jsonl The Python portion is split into three main blocks. Deduplication block If the Stop hook runs multiple times for the same session (which can happen by Claude Code's design), we don't want to write the same entry twice. So we read the existing log and load session_id + tool_use_id combinations into a seen_ids set. seen_ids = set() if os.path.exists(out_path): with open(out_path, "r", ...) as f: for line in f: r = json.loads(line) if r.get("session_id") == sid and r.get("tool_use_id"): seen_ids.add(r["tool_use_id"]) Pass 1: build the index Read the transcript line by line. tool_use blocks with "name": "Agent" and a subagent_type go into the uses dict; tool_result blocks go into the results dict. uses = {} # tool_use_id -> (ts, name, input, caller) results = {} # tool_use_id -> (ts, is_error) for b in content: if b.get("type") == "tool_use" and b.get("name") == "Agent": inp = b.get("input") or {} if "subagent_type" not in inp: continue uses[uid] = (ts, b.get("name"), inp, b.get("caller")) elif b.get("type") == "tool_result": results[rid] = (ts, bool(b.get("is_error"))) Agent calls without a subagent_type are skipped. This check exists to exclude invocations of the main Claude agent itself. Pass 2: match and write Iterate over uses, and if a matching results entry exists, compute duration_ms and write it out. t0 = parse_ts(use_ts) # tool_use のタイムスタンプ t1 = parse_ts(res_ts) # tool_result のタイムスタンプ if t0 and t1: duration_ms = int((t1 - t0).total_seconds() * 1000) Entries whose result hasn't come back yet are recorded with "status": "pending". The description field is truncated at 300 characters. This keeps the log file size under control even when the instructions given to an agent are long. if len(description) > 300: description = description[:300] + "…" A single line of the resulting JSONL looks like this. { "ts": "2026-09-10T08:30:00Z", "session_id": "abc123", "cwd": "~/dev/my-project", "tool_use_id": "toolu_01Xyz...", "subagent_type": "Explore", "description": "Find all TypeScript files that reference the Auth module…", "duration_ms": 18420, "status": "ok", "caller": null } To summarize the fields: subagent_type is the agent kind, duration_ms is the execution time in milliseconds, and status is one of "ok" / "error" / "pending". caller holds information about the caller, but it's null most of the time. Why two passes When you read a tool_use in a single pass, the matching tool_result may not have appeared yet. JSONL is in chronological order, but during a long agent run, other messages can be interleaved. Reading every line first to build an index and matching afterward — the two-pass structure — guarantees you get the pairs. Also, when the parse_ts function converts ISO 8601 timestamps to datetime objects, it replaces the trailing Z with +00:00 before passing to fromisoformat. def parse_ts(s): try: return datetime.datetime.fromisoformat(s.replace("Z", "+00:00")) except Exception: return None Python's fromisoformat can't parse the Z suffix directly before 3.11, so this conversion is required. How the log accumulates The script opens the file in "a" (append) mode. Each session adds new records to the end. If the file doesn't exist, it's created automatically (guaranteed by mkdir -p on LOG_DIR). Because data accumulates across sessions, after days or weeks of use, patterns emerge: "the Explore agent always takes over 20 seconds," "the code-reviewer agent errors out occasionally." Dissecting the cost log script Running alongside stop_agent_tracker.sh is stop_cost_log.sh. This one records the tokens consumed in a session and the estimated cost to ~/.claude/logs/cost-log.jsonl. Alongside agent slowness, knowing "when, in which session, and how much it cost" is essential for keeping a high-volume environment running. The PRICING table and prefix matching The rate table is implemented like this. PRICING = { "claude-opus-4-7": {"input": 15.0, "output": 75.0, "cache_read": 1.5, "cache_create_5m": 18.75, "cache_create_1h": 30.0}, "claude-sonnet-4-6": {"input": 3.0, "output": 15.0, "cache_read": 0.3, "cache_create_5m": 3.75, "cache_create_1h": 6.0}, "claude-haiku-4-5": {"input": 1.0, "output": 5.0, "cache_read": 0.1, "cache_create_5m": 1.25, "cache_create_1h": 2.0}, } DEFAULT_RATE = PRICING["claude-sonnet-4-6"] def rate_for(model: str): for k, v in PRICING.items(): if model.startswith(k): return v return DEFAULT_RATE The key point is that dictionary keys are matched by prefix (startswith) rather than exact match. Model names Claude Code writes to the transcript can carry a release-date suffix, like claude-sonnet-4-6-20250620. With exact matching, you'd have to rewrite PRICING every time a minor version updates. Prefix matching absorbs suffix changes. Unknown models fall back to DEFAULT_RATE (Sonnet-equivalent), so aggregation doesn't stop when a model not in the table shows up. 5-minute vs. 1-hour cache tokens The Anthropic API has two kinds of cache: a 5-minute ephemeral cache and a 1-hour cache, priced differently (roughly a 1:1.6 ratio). The script tallies them separately. cc_5m = (usage.get("cache_creation", {}) or {}).get("ephemeral_5m_input_tokens", 0) or 0 cc_1h = (usage.get("cache_creation", {}) or {}).get("ephemeral_1h_input_tokens", 0) or 0 if cc_5m + cc_1h == 0 and cc_total > 0: cc_5m = cc_total The last three lines are a consistency check. In older Claude Code versions or under certain conditions, the nested cache_creation object doesn't exist and only a flat cache_creation_input_tokens is returned. That yields cc_5m + cc_1h == 0 with cc_total > 0, so the full amount is treated as the 5-minute tier. Since the 5-minute tier is cheaper, this biases toward underestimating cost. I decided that's easier to reason about than overestimating. The cost formula cost_usd += ( inp / 1_000_000 * r["input"] + out / 1_000_000 * r["output"] + cr / 1_000_000 * r["cache_read"] + cc_5m / 1_000_000 * r["cache_create_5m"] + cc_1h / 1_000_000 * r["cache_create_1h"] ) The unit is "$/MTok" (dollars per million tokens), so the token count is divided by 1_000_000 before multiplying. The _-separated numeric literals are for readability and work on Python 3.6+. The script walks every message in the session, accumulates cost_usd, and finally rounds to four decimal places with round(cost_usd, 4). Aggregating the ledger with jq Once the log builds up, you can ask it questions with jq. All of the following are real queries against ~/.claude/logs/agent-invocations.jsonl. Average and max execution time per agent type jq -s ' group_by(.subagent_type) | map({ type: .[0].subagent_type, count: length, avg_ms: (map(select(.duration_ms != null) | .duration_ms) | add / length | round), max_ms: (map(select(.duration_ms != null) | .duration_ms) | max) }) | sort_by(-.avg_ms) ' ~/.claude/logs/agent-invocations.jsonl group_by buckets by type, then avg_ms and max_ms are computed and sorted descending. When I actually ran this, my environment showed the Explore agent averaging around 22 seconds, code-reviewer averaging 37 seconds, and general-purpose averaging 18 seconds. code-reviewer is slow because it reads multiple files — and once that was confirmed by numbers, my hunch that "using code-reviewer for multi-file checks is heavy" finally had backing. Identify agents with high error rates jq -s ' group_by(.subagent_type) | map({ type: .[0].subagent_type, total: length, errors: map(select(.status == "error")) | length, error_rate: ((map(select(.status == "error")) | length) / length * 100 | round) }) | sort_by(-.error_rate) ' ~/.claude/logs/agent-invocations.jsonl Sum cost for a specific project (cwd) jq -s ' map(select(.cwd | contains("my-project"))) | { total_cost: (map(.cost_usd) | add) } ' ~/.claude/logs/cost-log.jsonl The cost log also has a cwd field, so you can filter by project path and get a total. Once you can see how much you've spent on which project at a glance, your sense of profitability changes. Where I got stuck I hit four concrete snags before the implementation was done. All of them were the "why doesn't this work?" kind of bug, where the symptom alone hides the cause. Pitfall ①: stdin comes up empty and Python processes nothing In the first version, I wired shell and Python together like this. cat | python3 -