Skip to content

Commit 04eca98

Browse files
committed
fix(hooks): wire hook timing recording + delete dead HookTimer (#1494)
- Add hooks/lib/hook_runtime.py with time_hook() context manager that records hook elapsed time via SessionStats.record_hook_timing() - Wire time_hook into all 5 hook scripts: PreToolUse, PostToolUse, SessionStart, Stop, UserPromptSubmit - Delete hooks/lib/hook_timer.py (dead code — per-process in-memory model does not work for short-lived hook processes) - Delete tests/test_hook_timer.py (tests for removed dead code) - Add TestHookTimingWiring regression tests (3 cases): recording, exception resilience, accumulation The Stop hook summary now surfaces ⏱ timing data: [CB] 3m | 12 tools | 0 errors | Bash:5 | ⏱ PostToolUse:42ms
1 parent 2a2a4b4 commit 04eca98

9 files changed

Lines changed: 140 additions & 204 deletions

File tree

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
"""Hook execution timing context manager (#1494).
2+
3+
Records hook elapsed time via SessionStats.record_hook_timing(), flushing
4+
to disk so the Stop hook summary can surface the ⏱ timing report.
5+
"""
6+
import time
7+
from contextlib import contextmanager
8+
from typing import Optional
9+
10+
11+
@contextmanager
12+
def time_hook(
13+
hook_name: str,
14+
*,
15+
session_id: Optional[str] = None,
16+
data_dir: Optional[str] = None,
17+
):
18+
"""Context manager that records hook execution time.
19+
20+
Wraps hook logic with monotonic clock measurements and persists the
21+
elapsed milliseconds to disk via SessionStats. Recording failures
22+
are silently swallowed so hook execution is never blocked.
23+
24+
Args:
25+
hook_name: Claude Code event name (e.g. 'PostToolUse').
26+
session_id: Explicit session ID. If None, resolved via
27+
session_utils.get_session_id().
28+
data_dir: Stats directory override (mainly for tests).
29+
30+
Usage::
31+
32+
with time_hook("PostToolUse"):
33+
# ... hook logic ...
34+
"""
35+
start = time.monotonic()
36+
try:
37+
yield
38+
finally:
39+
try:
40+
elapsed_ms = (time.monotonic() - start) * 1000
41+
if session_id is None:
42+
from session_utils import get_session_id
43+
session_id = get_session_id()
44+
from stats import SessionStats
45+
kwargs = {"session_id": session_id}
46+
if data_dir is not None:
47+
kwargs["data_dir"] = data_dir
48+
stats = SessionStats(**kwargs)
49+
stats.record_hook_timing(hook_name, elapsed_ms)
50+
stats.flush()
51+
except Exception:
52+
pass # Never block tool execution

packages/claude-code-plugin/hooks/lib/hook_timer.py

Lines changed: 0 additions & 86 deletions
This file was deleted.

packages/claude-code-plugin/hooks/post-tool-use.py

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -26,6 +26,13 @@ def handle_post_tool_use(data: dict):
2626
Records tool call stats (#825).
2727
Future: history tracking (#827).
2828
"""
29+
from hook_runtime import time_hook
30+
with time_hook("PostToolUse"):
31+
return _handle_post_tool_use(data)
32+
33+
34+
def _handle_post_tool_use(data: dict):
35+
"""Core PostToolUse logic, wrapped by time_hook."""
2936
try:
3037
from stats import SessionStats
3138

packages/claude-code-plugin/hooks/pre-tool-use.py

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -289,7 +289,9 @@ def _handle(data: dict) -> Optional[dict]:
289289
@safe_main
290290
def handle_pre_tool_use(data: dict) -> Optional[dict]:
291291
"""Entry point for PreToolUse hook."""
292-
return _handle(data)
292+
from hook_runtime import time_hook
293+
with time_hook("PreToolUse"):
294+
return _handle(data)
293295

294296

295297
if __name__ == "__main__":

packages/claude-code-plugin/hooks/session-start.py

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -887,6 +887,14 @@ def _check_briefing_recovery() -> None:
887887

888888
def main():
889889
"""Main entry point for the session start hook."""
890+
_ensure_lib_path()
891+
from hook_runtime import time_hook
892+
with time_hook("SessionStart"):
893+
return _main_inner()
894+
895+
896+
def _main_inner():
897+
"""Core session-start logic, wrapped by time_hook."""
890898
try:
891899
home = Path.home()
892900
hooks_dir = home / ".claude" / "hooks"

packages/claude-code-plugin/hooks/stop.py

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,13 @@ def handle_stop(data: dict):
2323
2424
Finalizes session stats and returns a systemMessage summary.
2525
"""
26+
from hook_runtime import time_hook
27+
with time_hook("Stop"):
28+
return _handle_stop(data)
29+
30+
31+
def _handle_stop(data: dict):
32+
"""Core Stop logic, wrapped by time_hook."""
2633
try:
2734
from stats import SessionStats
2835

packages/claude-code-plugin/hooks/user-prompt-submit.py

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,18 @@ def detect_mode(prompt: str) -> Optional[str]:
5151

5252
def main():
5353
"""Main entry point for the hook."""
54+
# Ensure hooks/lib is importable for time_hook
55+
_hooks_dir = os.path.dirname(os.path.abspath(__file__))
56+
_lib_dir = os.path.join(_hooks_dir, "lib")
57+
if _lib_dir not in sys.path:
58+
sys.path.insert(0, _lib_dir)
59+
from hook_runtime import time_hook
60+
with time_hook("UserPromptSubmit"):
61+
return _main_inner()
62+
63+
64+
def _main_inner():
65+
"""Core UserPromptSubmit logic, wrapped by time_hook."""
5466
try:
5567
# Read input from stdin
5668
input_data = json.load(sys.stdin)

packages/claude-code-plugin/tests/test_hook_timer.py

Lines changed: 0 additions & 117 deletions
This file was deleted.

packages/claude-code-plugin/tests/test_stats.py

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -299,6 +299,57 @@ def test_concurrent_flush_no_lost_updates(self, data_dir):
299299
assert on_disk["tool_names"]["Bash"] == expected
300300

301301

302+
class TestHookTimingWiring:
303+
"""Regression test: hook scripts record timing via time_hook context manager (#1494)."""
304+
305+
def test_time_hook_records_timing(self, data_dir):
306+
"""time_hook should record elapsed_ms to disk hook_timings."""
307+
from hook_runtime import time_hook
308+
309+
session_id = "timing-test"
310+
SessionStats(session_id=session_id, data_dir=data_dir)
311+
312+
with time_hook("PostToolUse", session_id=session_id, data_dir=data_dir):
313+
time.sleep(0.01)
314+
315+
s = SessionStats(session_id=session_id, data_dir=data_dir)
316+
data = s._locked_read()
317+
assert "PostToolUse" in data["hook_timings"]
318+
assert len(data["hook_timings"]["PostToolUse"]) >= 1
319+
assert data["hook_timings"]["PostToolUse"][0] >= 5 # at least ~5ms
320+
321+
def test_time_hook_records_even_on_inner_exception(self, data_dir):
322+
"""Timing is recorded even when inner code raises."""
323+
from hook_runtime import time_hook
324+
325+
session_id = "exc-test"
326+
SessionStats(session_id=session_id, data_dir=data_dir)
327+
328+
with pytest.raises(ValueError):
329+
with time_hook("PostToolUse", session_id=session_id, data_dir=data_dir):
330+
raise ValueError("intentional error inside hook")
331+
332+
s = SessionStats(session_id=session_id, data_dir=data_dir)
333+
data = s._locked_read()
334+
assert "PostToolUse" in data["hook_timings"]
335+
assert len(data["hook_timings"]["PostToolUse"]) >= 1
336+
337+
def test_time_hook_records_multiple(self, data_dir):
338+
"""Multiple time_hook invocations accumulate timings."""
339+
from hook_runtime import time_hook
340+
341+
session_id = "multi-timing"
342+
SessionStats(session_id=session_id, data_dir=data_dir)
343+
344+
for _ in range(3):
345+
with time_hook("PreToolUse", session_id=session_id, data_dir=data_dir):
346+
pass
347+
348+
s = SessionStats(session_id=session_id, data_dir=data_dir)
349+
data = s._locked_read()
350+
assert len(data["hook_timings"]["PreToolUse"]) == 3
351+
352+
302353
class TestCleanup:
303354
def test_cleanup_stale_removes_old_files(self, data_dir):
304355
# Create a stale file

0 commit comments

Comments
 (0)