Skip to content

Commit be6502d

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 e85d111 commit be6502d

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
@@ -386,6 +386,57 @@ def test_concurrent_flush_no_lost_updates(self, data_dir):
386386
assert on_disk["tool_names"]["Bash"] == expected
387387

388388

389+
class TestHookTimingWiring:
390+
"""Regression test: hook scripts record timing via time_hook context manager (#1494)."""
391+
392+
def test_time_hook_records_timing(self, data_dir):
393+
"""time_hook should record elapsed_ms to disk hook_timings."""
394+
from hook_runtime import time_hook
395+
396+
session_id = "timing-test"
397+
SessionStats(session_id=session_id, data_dir=data_dir)
398+
399+
with time_hook("PostToolUse", session_id=session_id, data_dir=data_dir):
400+
time.sleep(0.01)
401+
402+
s = SessionStats(session_id=session_id, data_dir=data_dir)
403+
data = s._locked_read()
404+
assert "PostToolUse" in data["hook_timings"]
405+
assert len(data["hook_timings"]["PostToolUse"]) >= 1
406+
assert data["hook_timings"]["PostToolUse"][0] >= 5 # at least ~5ms
407+
408+
def test_time_hook_records_even_on_inner_exception(self, data_dir):
409+
"""Timing is recorded even when inner code raises."""
410+
from hook_runtime import time_hook
411+
412+
session_id = "exc-test"
413+
SessionStats(session_id=session_id, data_dir=data_dir)
414+
415+
with pytest.raises(ValueError):
416+
with time_hook("PostToolUse", session_id=session_id, data_dir=data_dir):
417+
raise ValueError("intentional error inside hook")
418+
419+
s = SessionStats(session_id=session_id, data_dir=data_dir)
420+
data = s._locked_read()
421+
assert "PostToolUse" in data["hook_timings"]
422+
assert len(data["hook_timings"]["PostToolUse"]) >= 1
423+
424+
def test_time_hook_records_multiple(self, data_dir):
425+
"""Multiple time_hook invocations accumulate timings."""
426+
from hook_runtime import time_hook
427+
428+
session_id = "multi-timing"
429+
SessionStats(session_id=session_id, data_dir=data_dir)
430+
431+
for _ in range(3):
432+
with time_hook("PreToolUse", session_id=session_id, data_dir=data_dir):
433+
pass
434+
435+
s = SessionStats(session_id=session_id, data_dir=data_dir)
436+
data = s._locked_read()
437+
assert len(data["hook_timings"]["PreToolUse"]) == 3
438+
439+
389440
class TestCleanup:
390441
def test_cleanup_stale_removes_old_files(self, data_dir):
391442
# Create a stale file

0 commit comments

Comments
 (0)