Skip to content

Commit 6671fd2

Browse files
luiseimanclaude
andcommitted
feat: tool-latency.sh — capture per-tool duration_ms (v3.4.0 follow-up)
Closes the v3.4.0 follow-up flagged in ROADMAP. The duration_ms field landed in PostToolUse / PostToolUseFailure payloads in Claude Code v2.1.119, but session-report.sh (Stop hook) has no access to per-tool stdin. This splits the responsibility: - template/hooks/tool-latency.sh — new PostToolUse hook (matcher: ""), reads tool_name + duration_ms from stdin and appends "tool|ms" to /tmp/claude-tool-latency-<hash>. Silent (exit 0). Back-compat with Claude Code <v2.1.119: missing/non-numeric duration_ms is a no-op, no garbage written. - template/hooks/session-report.sh — reads the counter at session end, computes tool_calls / tool_time_ms / tool_slowest, deletes the file, participates in same-day session merge, emits to JSON metrics and SESSION_REPORT.md. - template/settings.json.tmpl — wires the hook into PostToolUse with a separate matcher entry alongside lint-on-save / detect-stack-drift. - tests/test-tool-latency.sh — 7 cases: happy path, accumulation, missing duration_ms, non-numeric duration, pipe sanitization in tool_name, empty stdin, session-report aggregation logic. Defensive coding follows v3.3.1 lessons: integer sanitization with ${var//[!0-9]/} + ${var:-0}, awk regex guard against non-numeric rows, no `set -e` (grep no-match would kill the hook). Verified: tool-latency 7/7 + skills-index 19/19 + hooks 9/10 (1 pre-existing fail unrelated) + runtime 8/8 + compiler 1/1 + behavior CLI 5/5. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
1 parent 787dcc0 commit 6671fd2

4 files changed

Lines changed: 171 additions & 1 deletion

File tree

template/hooks/session-report.sh

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -49,6 +49,20 @@ if [[ -f "$LINT_COUNTER" ]]; then
4949
rm -f "$LINT_COUNTER"
5050
fi
5151

52+
# Tool-latency counter (written by tool-latency.sh — Claude Code v2.1.119+)
53+
LATENCY_COUNTER="/tmp/claude-tool-latency-${PROJECT_HASH}"
54+
TOOL_CALLS=0
55+
TOOL_TIME_MS=0
56+
TOOL_SLOWEST="none"
57+
if [[ -f "$LATENCY_COUNTER" ]]; then
58+
TOOL_CALLS=$(wc -l < "$LATENCY_COUNTER" | tr -d ' '); TOOL_CALLS=${TOOL_CALLS//[!0-9]/}; TOOL_CALLS=${TOOL_CALLS:-0}
59+
if (( TOOL_CALLS > 0 )); then
60+
TOOL_TIME_MS=$(awk -F'|' 'BEGIN{s=0} {if($2 ~ /^[0-9]+$/) s+=$2} END{print s+0}' "$LATENCY_COUNTER")
61+
TOOL_SLOWEST=$(awk -F'|' '$2 ~ /^[0-9]+$/ {if ($2+0 > max) {max=$2+0; tool=$1}} END{if (tool!="") printf "%s=%dms", tool, max; else print "none"}' "$LATENCY_COUNTER")
62+
fi
63+
rm -f "$LATENCY_COUNTER"
64+
fi
65+
5266
# --- Rule coverage ---
5367
# Cross-reference files touched against globs in .claude/rules/*.md
5468
RULES_DIR=".claude/rules"
@@ -121,13 +135,17 @@ if [[ -f "$METRICS_FILE" ]] && command -v jq &>/dev/null && jq -e . "$METRICS_FI
121135
PREV_FILES=$(_jq_num '.files_touched')
122136
PREV_COMMITS=$(_jq_num '.commits')
123137
PREV_SESSIONS=$(_jq_num '.sessions')
138+
PREV_TOOL_CALLS=$(_jq_num '.tool_calls')
139+
PREV_TOOL_TIME=$(_jq_num '.tool_time_ms')
124140

125141
ERRORS_ADDED=$((ERRORS_ADDED + PREV_ERRORS))
126142
HOOK_BLOCKS=$((HOOK_BLOCKS + PREV_HOOK))
127143
LINT_BLOCKS=$((LINT_BLOCKS + PREV_LINT))
128144
FILES_TOUCHED=$((FILES_TOUCHED + PREV_FILES))
129145
COMMITS=$((COMMITS + PREV_COMMITS))
130146
SESSIONS=$((PREV_SESSIONS + 1))
147+
TOOL_CALLS=$((TOOL_CALLS + PREV_TOOL_CALLS))
148+
TOOL_TIME_MS=$((TOOL_TIME_MS + PREV_TOOL_TIME))
131149
else
132150
SESSIONS=1
133151
fi
@@ -145,7 +163,10 @@ cat > "$METRICS_FILE" << JSON
145163
"rules_total": $TOTAL_RULES,
146164
"rule_coverage": $RULE_COVERAGE,
147165
"commits": $COMMITS,
148-
"domain_knowledge_updated": $DOMAIN_CHANGES
166+
"domain_knowledge_updated": $DOMAIN_CHANGES,
167+
"tool_calls": $TOOL_CALLS,
168+
"tool_time_ms": $TOOL_TIME_MS,
169+
"tool_slowest": "$TOOL_SLOWEST"
149170
}
150171
JSON
151172

@@ -179,6 +200,7 @@ if [[ "${FORGE_SESSION_REPORT:-false}" == "true" ]]; then
179200
- Hook blocks: $HOOK_BLOCKS (destructive) / $LINT_BLOCKS (lint)
180201
- Rule coverage: $RULES_MATCHED/$TOTAL_RULES ($RULE_COVERAGE)
181202
- Errors logged: $ERRORS_ADDED
203+
- Tool calls: $TOOL_CALLS (total ${TOOL_TIME_MS}ms; slowest: $TOOL_SLOWEST)
182204
183205
### Files
184206
$(echo "$RECENT_FILES" | sed 's/^/- /' 2>/dev/null)

template/hooks/tool-latency.sh

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,36 @@
1+
#!/usr/bin/env bash
2+
# PostToolUse hook: capture per-tool duration_ms (v2.1.119+) for session-report.
3+
# Matcher: "" (all tools).
4+
# Output: appends "tool_name|duration_ms" lines to /tmp/claude-tool-latency-<hash>.
5+
# Silent (exit 0) — telemetry only, never blocks.
6+
#
7+
# Back-compat: if duration_ms is absent or non-numeric (older Claude Code),
8+
# this hook is a no-op. session-report.sh handles a missing counter file.
9+
10+
# --- Project hash (must match session-report.sh) ---
11+
_hash() {
12+
printf '%s' "$1" | md5sum 2>/dev/null | cut -c1-8 || \
13+
printf '%s' "$1" | md5 -q 2>/dev/null | cut -c1-8 || \
14+
printf '%s' "$1" | cksum | cut -d' ' -f1
15+
}
16+
PROJECT_HASH=$(_hash "$PWD")
17+
COUNTER="/tmp/claude-tool-latency-${PROJECT_HASH}"
18+
19+
# --- Read stdin JSON (PostToolUse payload) ---
20+
PAYLOAD=$(cat)
21+
[[ -z "$PAYLOAD" ]] && exit 0
22+
23+
# --- Parse fields (jq required; degrade silently if absent) ---
24+
command -v jq >/dev/null 2>&1 || exit 0
25+
26+
TOOL_NAME=$(printf '%s' "$PAYLOAD" | jq -r '.tool_name // empty' 2>/dev/null)
27+
DURATION=$(printf '%s' "$PAYLOAD" | jq -r '.duration_ms // empty' 2>/dev/null)
28+
29+
# Sanitize: tool_name without pipes; duration must be a non-negative integer
30+
[[ -z "$TOOL_NAME" || -z "$DURATION" ]] && exit 0
31+
TOOL_NAME=${TOOL_NAME//|/_}
32+
DURATION=${DURATION//[!0-9]/}
33+
[[ -z "$DURATION" ]] && exit 0
34+
35+
printf '%s|%s\n' "$TOOL_NAME" "$DURATION" >> "$COUNTER" 2>/dev/null || true
36+
exit 0

template/settings.json.tmpl

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -122,6 +122,16 @@
122122
"timeout": 5
123123
}
124124
]
125+
},
126+
{
127+
"matcher": "",
128+
"hooks": [
129+
{
130+
"type": "command",
131+
"command": ".claude/hooks/tool-latency.sh",
132+
"timeout": 5
133+
}
134+
]
125135
}
126136
],
127137
"Stop": [

tests/test-tool-latency.sh

Lines changed: 102 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,102 @@
1+
#!/usr/bin/env bash
2+
# Test suite for tool-latency.sh PostToolUse hook
3+
# Run: bash tests/test-tool-latency.sh
4+
5+
set -u
6+
SCRIPT_DIR="$(cd "$(dirname "$0")" && pwd)"
7+
ROOT_DIR="$(dirname "$SCRIPT_DIR")"
8+
HOOK="$ROOT_DIR/template/hooks/tool-latency.sh"
9+
PASSED=0; FAILED=0
10+
11+
pass() { echo "$1"; PASSED=$((PASSED+1)); }
12+
fail() { echo "$1: $2"; FAILED=$((FAILED+1)); }
13+
14+
# Run hook in an isolated tmpdir so PROJECT_HASH is deterministic and
15+
# the counter file does not collide with the user's real metrics.
16+
WORK=$(mktemp -d)
17+
trap 'rm -rf "$WORK"' EXIT
18+
cd "$WORK"
19+
20+
# md5 hash of the temp PWD — must match _hash() in the hook
21+
HASH=$(printf '%s' "$PWD" | md5sum 2>/dev/null | cut -c1-8 || \
22+
printf '%s' "$PWD" | md5 -q 2>/dev/null | cut -c1-8 || \
23+
printf '%s' "$PWD" | cksum | cut -d' ' -f1)
24+
COUNTER="/tmp/claude-tool-latency-${HASH}"
25+
rm -f "$COUNTER"
26+
27+
echo "═══ tool-latency.sh tests ═══"
28+
29+
# 1. Happy path: tool_name + duration_ms numeric → one line appended
30+
echo '{"tool_name":"Bash","duration_ms":234,"hook_event_name":"PostToolUse"}' | bash "$HOOK"
31+
if [[ -f "$COUNTER" ]] && grep -qE '^Bash\|234$' "$COUNTER"; then
32+
pass "happy path: writes 'Bash|234'"
33+
else
34+
fail "happy path" "expected 'Bash|234' line in $COUNTER, got: $(cat "$COUNTER" 2>/dev/null || echo '<missing>')"
35+
fi
36+
37+
# 2. Multiple calls accumulate
38+
echo '{"tool_name":"Edit","duration_ms":12}' | bash "$HOOK"
39+
echo '{"tool_name":"Read","duration_ms":3}' | bash "$HOOK"
40+
LINES=$(wc -l < "$COUNTER" | tr -d ' ')
41+
if [[ "$LINES" == "3" ]]; then
42+
pass "accumulates across calls (3 lines)"
43+
else
44+
fail "accumulates" "expected 3 lines, got $LINES"
45+
fi
46+
47+
# 3. Missing duration_ms → no-op (back-compat with Claude Code <v2.1.119)
48+
rm -f "$COUNTER"
49+
echo '{"tool_name":"Bash"}' | bash "$HOOK"
50+
if [[ ! -f "$COUNTER" ]]; then
51+
pass "missing duration_ms → no-op"
52+
else
53+
fail "missing duration_ms" "counter should not exist; got: $(cat "$COUNTER")"
54+
fi
55+
56+
# 4. Non-numeric duration → no-op (defensive)
57+
rm -f "$COUNTER"
58+
echo '{"tool_name":"Bash","duration_ms":"slow"}' | bash "$HOOK"
59+
if [[ ! -f "$COUNTER" ]]; then
60+
pass "non-numeric duration_ms → no-op"
61+
else
62+
fail "non-numeric duration" "counter should not exist; got: $(cat "$COUNTER")"
63+
fi
64+
65+
# 5. Pipe in tool_name is sanitized (won't break the parser)
66+
rm -f "$COUNTER"
67+
echo '{"tool_name":"weird|tool","duration_ms":7}' | bash "$HOOK"
68+
if grep -qE '^weird_tool\|7$' "$COUNTER"; then
69+
pass "pipe in tool_name sanitized to _"
70+
else
71+
fail "pipe sanitization" "expected 'weird_tool|7', got: $(cat "$COUNTER")"
72+
fi
73+
74+
# 6. Empty stdin → no-op, exit 0
75+
rm -f "$COUNTER"
76+
printf '' | bash "$HOOK"
77+
RC=$?
78+
if [[ "$RC" == "0" && ! -f "$COUNTER" ]]; then
79+
pass "empty stdin → exit 0, no-op"
80+
else
81+
fail "empty stdin" "rc=$RC, counter exists=$([[ -f $COUNTER ]] && echo yes || echo no)"
82+
fi
83+
84+
# 7. Aggregation logic that session-report.sh uses (simulated)
85+
rm -f "$COUNTER"
86+
for d in 100 50 800 30; do
87+
echo "{\"tool_name\":\"Bash\",\"duration_ms\":$d}" | bash "$HOOK"
88+
done
89+
TOTAL=$(awk -F'|' 'BEGIN{s=0} {if($2 ~ /^[0-9]+$/) s+=$2} END{print s+0}' "$COUNTER")
90+
SLOWEST=$(awk -F'|' '$2 ~ /^[0-9]+$/ {if ($2+0 > max) {max=$2+0; tool=$1}} END{if (tool!="") printf "%s=%dms", tool, max; else print "none"}' "$COUNTER")
91+
if [[ "$TOTAL" == "980" && "$SLOWEST" == "Bash=800ms" ]]; then
92+
pass "session-report aggregation: total=980ms, slowest=Bash=800ms"
93+
else
94+
fail "aggregation" "total=$TOTAL slowest=$SLOWEST (expected 980 + Bash=800ms)"
95+
fi
96+
97+
rm -f "$COUNTER"
98+
99+
echo
100+
echo "----------"
101+
echo "$PASSED passed, $FAILED failed"
102+
[[ "$FAILED" == "0" ]] && exit 0 || exit 1

0 commit comments

Comments
 (0)