44``record(...)`` call sites then accumulate per-loop stats that
55``report()`` formats as a table.
66
7- Cost when disabled: a single global-var read per ``record`` call.
8- Cost when enabled: a dict lookup + list append per loop exit.
7+ A second metric class -- wall-clock timers -- is exposed via
8+ ``timer(site)``. Same env-var gate, same ``report()`` output (second
9+ table). Both classes share the site namespace, so a site may appear in
10+ both tables (e.g., ``EqRPS.outer`` records iters; ``EqRPS.apply``
11+ records wall-clock).
12+
13+ Cost when disabled: a single global-var read per ``record`` / ``timer``
14+ call (the latter returns a shared no-op context-manager singleton).
15+ Cost when enabled: a dict lookup + list append per loop exit, plus a
16+ ``perf_counter`` pair + accumulate per ``timer`` exit.
917"""
1018from __future__ import annotations
1119
1220import os
1321import sys
22+ import time
1423from collections import defaultdict
1524from typing import Optional
1625
@@ -21,7 +30,12 @@ def _new_bucket():
2130 return {'entries' : 0 , 'iters' : [], 'hit_cap' : 0 , 'early_exit' : 0 , 'caps' : set ()}
2231
2332
33+ def _new_timer_bucket ():
34+ return {'entries' : 0 , 'total_s' : 0.0 , 'max_s' : 0.0 }
35+
36+
2437_stats = defaultdict (_new_bucket )
38+ _timers = defaultdict (_new_timer_bucket )
2539
2640
2741def enabled () -> bool :
@@ -48,8 +62,78 @@ def record(site: str, iters: int, cap: int) -> None:
4862 b ['early_exit' ] += 1
4963
5064
65+ class _ActiveTimer :
66+ """Per-call active timer; one instance per ``with timer(site):``."""
67+ __slots__ = ('_site' , '_t0' )
68+
69+ def __init__ (self , site : str ) -> None :
70+ self ._site = site
71+ self ._t0 = 0.0
72+
73+ def __enter__ (self ):
74+ self ._t0 = time .perf_counter ()
75+ return self
76+
77+ def __exit__ (self , exc_type , exc , tb ):
78+ dt = time .perf_counter () - self ._t0
79+ b = _timers [self ._site ]
80+ b ['entries' ] += 1
81+ b ['total_s' ] += dt
82+ if dt > b ['max_s' ]:
83+ b ['max_s' ] = dt
84+ return False
85+
86+
87+ class _NoopTimer :
88+ """Singleton CM returned when ``EPDE_LOOP_STATS`` is off."""
89+ __slots__ = ()
90+
91+ def __enter__ (self ):
92+ return self
93+
94+ def __exit__ (self , exc_type , exc , tb ):
95+ return False
96+
97+
98+ _NOOP_TIMER = _NoopTimer ()
99+
100+
101+ def timer (site : str ):
102+ """Return a context manager that accumulates wall-clock under ``site``.
103+
104+ Disabled fast path: returns a shared singleton no-op CM; the
105+ ``with`` block then costs one __enter__/__exit__ method call and
106+ nothing else. Enabled path: allocates a small ``_ActiveTimer``
107+ per call.
108+ """
109+ if not _ENABLED :
110+ return _NOOP_TIMER
111+ return _ActiveTimer (site )
112+
113+
114+ def timed (site : str ):
115+ """Decorator wrapping ``fn`` with ``timer(site)``.
116+
117+ Avoids re-indenting large ``apply`` bodies when adding probes. When
118+ ``EPDE_LOOP_STATS`` is off, cost is one extra function call + the
119+ no-op CM enter/exit, all of which are negligible compared to the
120+ wrapped operator work.
121+ """
122+ def deco (fn ):
123+ def wrapper (* args , ** kwargs ):
124+ with timer (site ):
125+ return fn (* args , ** kwargs )
126+ wrapper .__wrapped__ = fn
127+ wrapper .__name__ = getattr (fn , '__name__' , 'wrapper' )
128+ wrapper .__qualname__ = getattr (fn , '__qualname__' , 'wrapper' )
129+ wrapper .__doc__ = fn .__doc__
130+ return wrapper
131+ return deco
132+
133+
51134def reset () -> None :
52135 _stats .clear ()
136+ _timers .clear ()
53137
54138
55139def _stats_for (name : str ) -> dict :
@@ -73,8 +157,17 @@ def _stats_for(name: str) -> dict:
73157 }
74158
75159
160+ def timers_snapshot () -> dict :
161+ """Return a copy of the timers dict for external consumers.
162+
163+ Used by ``profile_loop_stats.py`` to build the cross-system
164+ compare table without re-parsing the report text.
165+ """
166+ return {site : dict (b ) for site , b in _timers .items ()}
167+
168+
76169def report (path : Optional [str ] = None ) -> str :
77- """Format all recorded loops as a table, sorted by total iterations .
170+ """Format all recorded loops + timers as two tables .
78171
79172 Writes to ``path`` if given AND also returns the string.
80173 """
@@ -84,6 +177,7 @@ def report(path: Optional[str] = None) -> str:
84177 header = (f"{ 'site' :<45} { 'entries' :>8} { 'mean' :>7} { 'med' :>5} "
85178 f"{ 'p95' :>5} { 'max' :>5} { 'cap' :>6} { '%cap' :>6} "
86179 f"{ '%early' :>7} { 'totIters' :>10} " )
180+ lines .append ('LOOPS' )
87181 lines .append (header )
88182 lines .append ('-' * len (header ))
89183 if not _ENABLED :
@@ -99,6 +193,34 @@ def report(path: Optional[str] = None) -> str:
99193 f"{ cap_str :>6} { s ['hit_cap_pct' ]:>5.1f} % "
100194 f"{ s ['early_exit_pct' ]:>6.1f} % { s ['total_iters' ]:>10d} "
101195 )
196+
197+ lines .append ('' )
198+ timer_sites = sorted (_timers .keys (),
199+ key = lambda s : - _timers [s ]['total_s' ])
200+ timer_header = (f"{ 'site' :<45} { 'entries' :>8} { 'total_s' :>10} "
201+ f"{ 'mean_ms' :>10} { 'max_ms' :>10} { 'share%' :>7} " )
202+ lines .append ('TIMERS' )
203+ lines .append (timer_header )
204+ lines .append ('-' * len (timer_header ))
205+ if not _ENABLED :
206+ lines .append ('(EPDE_LOOP_STATS disabled -- set EPDE_LOOP_STATS=1 to record)' )
207+ if timer_sites :
208+ total_max = max (_timers [s ]['total_s' ] for s in timer_sites )
209+ else :
210+ total_max = 0.0
211+ for site in timer_sites :
212+ b = _timers [site ]
213+ n = b ['entries' ]
214+ if n == 0 :
215+ continue
216+ mean_ms = 1000.0 * b ['total_s' ] / n
217+ max_ms = 1000.0 * b ['max_s' ]
218+ share = (100.0 * b ['total_s' ] / total_max ) if total_max > 0 else 0.0
219+ lines .append (
220+ f"{ site :<45} { n :>8d} { b ['total_s' ]:>10.2f} "
221+ f"{ mean_ms :>10.2f} { max_ms :>10.2f} { share :>6.1f} %"
222+ )
223+
102224 text = '\n ' .join (lines )
103225 if path is not None :
104226 with open (path , 'w' ) as f :
0 commit comments