690 lines
21 KiB
Python
690 lines
21 KiB
Python
"""Low-overhead, run-local performance instrumentation for simulations.
|
|
|
|
The profiling mode is intentionally read once when this module is imported.
|
|
``standard`` records low-frequency pipeline stages, while ``audit`` also wraps
|
|
hot RHS/property operations and computes exact-input reuse metrics. With
|
|
profiling disabled, decorators return the original callable while classes are
|
|
being defined, so ordinary simulation calls do not pass through a wrapper.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
from collections.abc import Callable, Generator, Mapping
|
|
from contextlib import contextmanager
|
|
from contextvars import ContextVar, Token
|
|
from dataclasses import dataclass, field
|
|
from functools import wraps
|
|
import inspect
|
|
import os
|
|
import struct
|
|
from time import perf_counter_ns
|
|
from typing import Any, Literal, ParamSpec, TypeVar, cast
|
|
|
|
|
|
ProfileMode = Literal["off", "standard", "audit"]
|
|
|
|
_P = ParamSpec("_P")
|
|
_R = TypeVar("_R")
|
|
_MODE_RANK: Mapping[ProfileMode, int] = {"off": 0, "standard": 1, "audit": 2}
|
|
|
|
|
|
def _read_startup_mode() -> ProfileMode:
|
|
raw_mode = os.getenv("SIMULATIONAPP_PROFILE", "off").strip().lower()
|
|
aliases: dict[str, ProfileMode] = {
|
|
"": "off",
|
|
"0": "off",
|
|
"false": "off",
|
|
"no": "off",
|
|
"off": "off",
|
|
"1": "standard",
|
|
"true": "standard",
|
|
"yes": "standard",
|
|
"on": "standard",
|
|
"standard": "standard",
|
|
"audit": "audit",
|
|
}
|
|
try:
|
|
return aliases[raw_mode]
|
|
except KeyError as exc:
|
|
raise ValueError(
|
|
"SIMULATIONAPP_PROFILE must be one of: off, standard, audit."
|
|
) from exc
|
|
|
|
|
|
PROFILE_MODE: ProfileMode = _read_startup_mode()
|
|
|
|
|
|
def _minimum_mode(value: str) -> ProfileMode:
|
|
normalized = value.strip().lower()
|
|
if normalized not in _MODE_RANK:
|
|
raise ValueError("minimum_mode must be one of: off, standard, audit.")
|
|
return cast(ProfileMode, normalized)
|
|
|
|
|
|
def _mode_enabled(minimum_mode: ProfileMode) -> bool:
|
|
# ``off`` is an unconditional zero-wrapper mode, even if a caller passes
|
|
# ``minimum_mode="off"`` by mistake.
|
|
return (
|
|
PROFILE_MODE != "off"
|
|
and _MODE_RANK[PROFILE_MODE] >= _MODE_RANK[minimum_mode]
|
|
)
|
|
|
|
|
|
@dataclass
|
|
class _TimingStats:
|
|
calls: int = 0
|
|
inclusive_ns: int = 0
|
|
self_ns: int = 0
|
|
max_ns: int = 0
|
|
errors: int = 0
|
|
|
|
def record(self, inclusive_ns: int, self_ns: int, error: bool) -> None:
|
|
self.calls += 1
|
|
self.inclusive_ns += inclusive_ns
|
|
self.self_ns += self_ns
|
|
self.max_ns = max(self.max_ns, inclusive_ns)
|
|
if error:
|
|
self.errors += 1
|
|
|
|
def snapshot(self) -> dict[str, int]:
|
|
return {
|
|
"calls": self.calls,
|
|
"inclusiveNs": self.inclusive_ns,
|
|
"selfNs": self.self_ns,
|
|
"maxNs": self.max_ns,
|
|
"errors": self.errors,
|
|
}
|
|
|
|
|
|
@dataclass
|
|
class _PropertyStats(_TimingStats):
|
|
operation: str = ""
|
|
layer: str = "semantic"
|
|
medium: str = "unknown"
|
|
exact_input_unique: int = 0
|
|
exact_input_repeats: int = 0
|
|
iteration_calls: int = 0
|
|
iteration_total: int = 0
|
|
iteration_max: int = 0
|
|
iteration_converged: int = 0
|
|
iteration_nonconverged: int = 0
|
|
cache_lookups: int = 0
|
|
cache_hits: int = 0
|
|
cache_misses: int = 0
|
|
|
|
def snapshot(self, *, audit: bool) -> dict[str, object]:
|
|
result: dict[str, object] = super().snapshot()
|
|
result.update(
|
|
{
|
|
"operation": self.operation,
|
|
"layer": self.layer,
|
|
"medium": self.medium,
|
|
"cacheLookups": self.cache_lookups,
|
|
"cacheHits": self.cache_hits,
|
|
"cacheMisses": self.cache_misses,
|
|
}
|
|
)
|
|
if audit:
|
|
result.update(
|
|
{
|
|
"exactInputUnique": self.exact_input_unique,
|
|
"exactInputRepeats": self.exact_input_repeats,
|
|
"iterationCalls": self.iteration_calls,
|
|
"iterationTotal": self.iteration_total,
|
|
"iterationMax": self.iteration_max,
|
|
"iterationConverged": self.iteration_converged,
|
|
"iterationNonconverged": self.iteration_nonconverged,
|
|
}
|
|
)
|
|
return result
|
|
|
|
|
|
@dataclass
|
|
class _ActiveSpan:
|
|
trace: PerformanceTrace
|
|
name: str
|
|
started_ns: int
|
|
property_key: str | None = None
|
|
property_operation: str | None = None
|
|
property_outermost: bool = False
|
|
child_ns: int = 0
|
|
|
|
|
|
@dataclass
|
|
class PerformanceTrace:
|
|
"""Mutable counters owned by exactly one :func:`profile_run` context."""
|
|
|
|
mode: ProfileMode
|
|
_phases: dict[str, _TimingStats] = field(default_factory=dict, repr=False)
|
|
_properties: dict[str, _PropertyStats] = field(default_factory=dict, repr=False)
|
|
_property_outermost_ns: int = field(default=0, repr=False)
|
|
|
|
@property
|
|
def enabled(self) -> bool:
|
|
return self.mode != "off"
|
|
|
|
def _property_stats(
|
|
self,
|
|
key: str,
|
|
*,
|
|
operation: str,
|
|
layer: str,
|
|
medium: str,
|
|
) -> _PropertyStats:
|
|
stats = self._properties.get(key)
|
|
if stats is None:
|
|
stats = _PropertyStats(
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
)
|
|
self._properties[key] = stats
|
|
return stats
|
|
|
|
def _record_span(self, frame: _ActiveSpan, elapsed_ns: int, error: bool) -> None:
|
|
self_ns = max(0, elapsed_ns - frame.child_ns)
|
|
if frame.property_key is None:
|
|
stats = self._phases.setdefault(frame.name, _TimingStats())
|
|
else:
|
|
layer, medium, operation = frame.property_key.split("|", 2)
|
|
stats = self._property_stats(
|
|
frame.property_key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
)
|
|
if frame.property_outermost:
|
|
self._property_outermost_ns += elapsed_ns
|
|
stats.record(elapsed_ns, self_ns, error)
|
|
|
|
def _record_exact_input(
|
|
self,
|
|
key: str,
|
|
*,
|
|
operation: str,
|
|
layer: str,
|
|
medium: str,
|
|
fingerprint: object,
|
|
) -> None:
|
|
stats = self._property_stats(
|
|
key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
)
|
|
shadow_key = (key, fingerprint)
|
|
shadow = _PROPERTY_SHADOW.get()
|
|
if shadow is None:
|
|
# A trace normally installs its own set in ``profile_run``. Keep
|
|
# the ContextVar default immutable so no task can accidentally
|
|
# share a process-global shadow set.
|
|
shadow = set()
|
|
_PROPERTY_SHADOW.set(shadow)
|
|
if shadow_key in shadow:
|
|
stats.exact_input_repeats += 1
|
|
else:
|
|
shadow.add(shadow_key)
|
|
stats.exact_input_unique += 1
|
|
|
|
def _record_iterations(
|
|
self,
|
|
key: str,
|
|
*,
|
|
operation: str,
|
|
layer: str,
|
|
medium: str,
|
|
iterations: int,
|
|
converged: bool,
|
|
) -> None:
|
|
stats = self._property_stats(
|
|
key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
)
|
|
iteration_count = max(0, int(iterations))
|
|
stats.iteration_calls += 1
|
|
stats.iteration_total += iteration_count
|
|
stats.iteration_max = max(stats.iteration_max, iteration_count)
|
|
if converged:
|
|
stats.iteration_converged += 1
|
|
else:
|
|
stats.iteration_nonconverged += 1
|
|
|
|
def _record_cache(
|
|
self,
|
|
key: str,
|
|
*,
|
|
operation: str,
|
|
layer: str,
|
|
medium: str,
|
|
hits: int,
|
|
misses: int,
|
|
) -> None:
|
|
stats = self._property_stats(
|
|
key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
)
|
|
hit_delta = max(0, hits)
|
|
miss_delta = max(0, misses)
|
|
stats.cache_hits += hit_delta
|
|
stats.cache_misses += miss_delta
|
|
stats.cache_lookups += hit_delta + miss_delta
|
|
|
|
def snapshot(self) -> dict[str, object]:
|
|
"""Return a detached, JSON-serializable copy of all counters."""
|
|
|
|
audit = self.mode == "audit"
|
|
return {
|
|
"mode": self.mode,
|
|
"phases": {
|
|
name: self._phases[name].snapshot()
|
|
for name in sorted(self._phases)
|
|
},
|
|
"properties": {
|
|
_public_property_key(key): self._properties[key].snapshot(audit=audit)
|
|
for key in sorted(self._properties)
|
|
},
|
|
"propertyOutermostNs": self._property_outermost_ns,
|
|
}
|
|
|
|
|
|
_CURRENT_TRACE: ContextVar[PerformanceTrace | None] = ContextVar(
|
|
"simulation_performance_trace",
|
|
default=None,
|
|
)
|
|
_ACTIVE_SPANS: ContextVar[tuple[_ActiveSpan, ...]] = ContextVar(
|
|
"simulation_performance_spans",
|
|
default=(),
|
|
)
|
|
_PROPERTY_SHADOW: ContextVar[set[object] | None] = ContextVar(
|
|
"simulation_property_shadow",
|
|
default=None,
|
|
)
|
|
|
|
|
|
def _public_property_key(key: str) -> str:
|
|
layer, medium, operation = key.split("|", 2)
|
|
return f"{layer}.{medium}.{operation}"
|
|
|
|
|
|
@contextmanager
|
|
def _tracked_span(
|
|
trace: PerformanceTrace,
|
|
name: str,
|
|
*,
|
|
property_key: str | None = None,
|
|
property_operation: str | None = None,
|
|
reset_property_shadow: bool = False,
|
|
) -> Generator[None, None, None]:
|
|
stack = _ACTIVE_SPANS.get()
|
|
property_outermost = property_key is not None and not any(
|
|
item.property_key is not None for item in stack
|
|
)
|
|
frame = _ActiveSpan(
|
|
trace=trace,
|
|
name=name,
|
|
started_ns=perf_counter_ns(),
|
|
property_key=property_key,
|
|
property_operation=property_operation,
|
|
property_outermost=property_outermost,
|
|
)
|
|
stack_token = _ACTIVE_SPANS.set((*stack, frame))
|
|
shadow_token: Token[set[object] | None] | None = None
|
|
if reset_property_shadow and trace.mode == "audit":
|
|
shadow_token = _PROPERTY_SHADOW.set(set())
|
|
error = False
|
|
try:
|
|
yield
|
|
except BaseException:
|
|
error = True
|
|
raise
|
|
finally:
|
|
elapsed_ns = max(0, perf_counter_ns() - frame.started_ns)
|
|
_ACTIVE_SPANS.reset(stack_token)
|
|
if shadow_token is not None:
|
|
_PROPERTY_SHADOW.reset(shadow_token)
|
|
if stack:
|
|
stack[-1].child_ns += elapsed_ns
|
|
trace._record_span(frame, elapsed_ns, error)
|
|
|
|
|
|
@contextmanager
|
|
def profile_run() -> Generator[PerformanceTrace, None, None]:
|
|
"""Create and bind an isolated trace for one simulation run.
|
|
|
|
The yielded trace remains usable after the context exits, which lets the
|
|
caller attach ``trace.snapshot()`` to a result without exposing live state.
|
|
"""
|
|
|
|
trace = PerformanceTrace(mode=PROFILE_MODE)
|
|
trace_token = _CURRENT_TRACE.set(trace)
|
|
spans_token = _ACTIVE_SPANS.set(())
|
|
shadow_token = _PROPERTY_SHADOW.set(set())
|
|
try:
|
|
if trace.enabled:
|
|
with _tracked_span(trace, "simulation.total"):
|
|
yield trace
|
|
else:
|
|
yield trace
|
|
finally:
|
|
_PROPERTY_SHADOW.reset(shadow_token)
|
|
_ACTIVE_SPANS.reset(spans_token)
|
|
_CURRENT_TRACE.reset(trace_token)
|
|
|
|
|
|
@contextmanager
|
|
def performance_span(
|
|
name: str,
|
|
minimum_mode: str = "standard",
|
|
reset_property_shadow: bool = False,
|
|
) -> Generator[None, None, None]:
|
|
"""Time a block in the current run, or act as a no-op outside one."""
|
|
|
|
minimum = _minimum_mode(minimum_mode)
|
|
trace = _CURRENT_TRACE.get()
|
|
if trace is None or not _mode_enabled(minimum):
|
|
yield
|
|
return
|
|
with _tracked_span(
|
|
trace,
|
|
name,
|
|
reset_property_shadow=reset_property_shadow,
|
|
):
|
|
yield
|
|
|
|
|
|
def profile_phase(
|
|
name: str,
|
|
minimum_mode: str = "standard",
|
|
reset_property_shadow: bool = False,
|
|
) -> Callable[[Callable[_P, _R]], Callable[_P, _R]]:
|
|
"""Decorate a simulation phase while preserving the off-mode callable."""
|
|
|
|
minimum = _minimum_mode(minimum_mode)
|
|
|
|
def decorate(function: Callable[_P, _R]) -> Callable[_P, _R]:
|
|
if not _mode_enabled(minimum):
|
|
return function
|
|
|
|
if inspect.iscoroutinefunction(function):
|
|
|
|
@wraps(function)
|
|
async def async_wrapper(*args: _P.args, **kwargs: _P.kwargs) -> Any:
|
|
trace = _CURRENT_TRACE.get()
|
|
if trace is None:
|
|
return await function(*args, **kwargs)
|
|
with _tracked_span(
|
|
trace,
|
|
name,
|
|
reset_property_shadow=reset_property_shadow,
|
|
):
|
|
return await function(*args, **kwargs)
|
|
|
|
return cast(Callable[_P, _R], async_wrapper)
|
|
|
|
@wraps(function)
|
|
def wrapper(*args: _P.args, **kwargs: _P.kwargs) -> _R:
|
|
trace = _CURRENT_TRACE.get()
|
|
if trace is None:
|
|
return function(*args, **kwargs)
|
|
with _tracked_span(
|
|
trace,
|
|
name,
|
|
reset_property_shadow=reset_property_shadow,
|
|
):
|
|
return function(*args, **kwargs)
|
|
|
|
return wrapper
|
|
|
|
return decorate
|
|
|
|
|
|
def _medium_name(args: tuple[object, ...]) -> str:
|
|
if not args:
|
|
return "unknown"
|
|
owner = args[0]
|
|
configured_name = getattr(owner, "name", None)
|
|
if isinstance(configured_name, str) and configured_name:
|
|
return configured_name
|
|
return type(owner).__name__
|
|
|
|
|
|
def _fingerprint(value: object) -> object:
|
|
"""Build a hashable, bit-exact token without retaining arbitrary objects."""
|
|
|
|
if value is None or isinstance(value, (bool, int, str, bytes)):
|
|
return (type(value).__name__, value)
|
|
if isinstance(value, float):
|
|
return ("float64", struct.pack("!d", value))
|
|
if isinstance(value, tuple):
|
|
return ("tuple", tuple(_fingerprint(item) for item in value))
|
|
if isinstance(value, list):
|
|
return ("list", tuple(_fingerprint(item) for item in value))
|
|
if isinstance(value, Mapping):
|
|
items = [(_fingerprint(key), _fingerprint(item)) for key, item in value.items()]
|
|
items.sort(key=repr)
|
|
return ("mapping", tuple(items))
|
|
return (
|
|
"object",
|
|
type(value).__module__,
|
|
type(value).__qualname__,
|
|
id(value),
|
|
)
|
|
|
|
|
|
def _input_fingerprint(
|
|
signature: inspect.Signature | None,
|
|
args: tuple[object, ...],
|
|
kwargs: dict[str, object],
|
|
) -> object:
|
|
if signature is not None:
|
|
try:
|
|
bound = signature.bind(*args, **kwargs)
|
|
bound.apply_defaults()
|
|
return tuple(
|
|
(name, _fingerprint(value))
|
|
for name, value in bound.arguments.items()
|
|
)
|
|
except TypeError:
|
|
pass
|
|
return (
|
|
_fingerprint(args),
|
|
tuple(sorted((name, _fingerprint(value)) for name, value in kwargs.items())),
|
|
)
|
|
|
|
|
|
def _cache_counts(function: Callable[..., object]) -> tuple[int, int] | None:
|
|
cache_info = getattr(function, "cache_info", None)
|
|
if not callable(cache_info):
|
|
return None
|
|
try:
|
|
info = cache_info()
|
|
return int(info.hits), int(info.misses)
|
|
except (AttributeError, TypeError, ValueError):
|
|
return None
|
|
|
|
|
|
def _copy_cache_api(source: Callable[..., object], target: Callable[..., object]) -> None:
|
|
for attribute in ("cache_clear", "cache_info", "cache_parameters"):
|
|
value = getattr(source, attribute, None)
|
|
if value is not None:
|
|
setattr(target, attribute, value)
|
|
|
|
|
|
def profile_property(
|
|
operation: str,
|
|
layer: str = "semantic",
|
|
minimum_mode: str = "audit",
|
|
capture_inputs: bool = True,
|
|
track_cache: bool = False,
|
|
) -> Callable[[Callable[_P, _R]], Callable[_P, _R]]:
|
|
"""Decorate one thermodynamic property operation."""
|
|
|
|
minimum = _minimum_mode(minimum_mode)
|
|
|
|
def decorate(function: Callable[_P, _R]) -> Callable[_P, _R]:
|
|
if not _mode_enabled(minimum):
|
|
return function
|
|
try:
|
|
signature: inspect.Signature | None = inspect.signature(function)
|
|
except (TypeError, ValueError):
|
|
signature = None
|
|
|
|
def prepare(
|
|
args: tuple[object, ...],
|
|
kwargs: dict[str, object],
|
|
) -> tuple[PerformanceTrace | None, str, str, tuple[int, int] | None]:
|
|
trace = _CURRENT_TRACE.get()
|
|
medium = _medium_name(args)
|
|
key = f"{layer}|{medium}|{operation}"
|
|
if trace is not None and trace.mode == "audit" and capture_inputs:
|
|
trace._record_exact_input(
|
|
key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
fingerprint=_input_fingerprint(signature, args, kwargs),
|
|
)
|
|
before = _cache_counts(function) if trace is not None and track_cache else None
|
|
return trace, medium, key, before
|
|
|
|
def finish_cache(
|
|
trace: PerformanceTrace | None,
|
|
medium: str,
|
|
key: str,
|
|
before: tuple[int, int] | None,
|
|
) -> None:
|
|
if trace is None or before is None:
|
|
return
|
|
after = _cache_counts(function)
|
|
if after is None:
|
|
return
|
|
trace._record_cache(
|
|
key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
hits=after[0] - before[0],
|
|
misses=after[1] - before[1],
|
|
)
|
|
|
|
if inspect.iscoroutinefunction(function):
|
|
|
|
@wraps(function)
|
|
async def async_wrapper(*args: _P.args, **kwargs: _P.kwargs) -> Any:
|
|
object_args = cast(tuple[object, ...], args)
|
|
object_kwargs = cast(dict[str, object], kwargs)
|
|
trace, medium, key, before = prepare(object_args, object_kwargs)
|
|
try:
|
|
if trace is None:
|
|
return await function(*args, **kwargs)
|
|
with _tracked_span(
|
|
trace,
|
|
f"property.{_public_property_key(key)}",
|
|
property_key=key,
|
|
property_operation=operation,
|
|
):
|
|
return await function(*args, **kwargs)
|
|
finally:
|
|
finish_cache(trace, medium, key, before)
|
|
|
|
_copy_cache_api(function, async_wrapper)
|
|
return cast(Callable[_P, _R], async_wrapper)
|
|
|
|
@wraps(function)
|
|
def wrapper(*args: _P.args, **kwargs: _P.kwargs) -> _R:
|
|
object_args = cast(tuple[object, ...], args)
|
|
object_kwargs = cast(dict[str, object], kwargs)
|
|
trace, medium, key, before = prepare(object_args, object_kwargs)
|
|
try:
|
|
if trace is None:
|
|
return function(*args, **kwargs)
|
|
with _tracked_span(
|
|
trace,
|
|
f"property.{_public_property_key(key)}",
|
|
property_key=key,
|
|
property_operation=operation,
|
|
):
|
|
return function(*args, **kwargs)
|
|
finally:
|
|
finish_cache(trace, medium, key, before)
|
|
|
|
_copy_cache_api(function, wrapper)
|
|
return wrapper
|
|
|
|
return decorate
|
|
|
|
|
|
def record_property_iterations(
|
|
operation: str,
|
|
iterations: int,
|
|
converged: bool,
|
|
) -> None:
|
|
"""Record inverse-property solver iterations in audit mode."""
|
|
|
|
trace = _CURRENT_TRACE.get()
|
|
if trace is None or trace.mode != "audit":
|
|
return
|
|
for frame in reversed(_ACTIVE_SPANS.get()):
|
|
if (
|
|
frame.property_key is not None
|
|
and frame.property_operation == operation
|
|
):
|
|
layer, medium, _unused_operation = frame.property_key.split("|", 2)
|
|
trace._record_iterations(
|
|
frame.property_key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
iterations=iterations,
|
|
converged=converged,
|
|
)
|
|
return
|
|
key = f"semantic|unknown|{operation}"
|
|
trace._record_iterations(
|
|
key,
|
|
operation=operation,
|
|
layer="semantic",
|
|
medium="unknown",
|
|
iterations=iterations,
|
|
converged=converged,
|
|
)
|
|
|
|
|
|
def record_property_cache(operation: str, *, hit: bool) -> None:
|
|
"""Record one run-local property-cache lookup in audit mode."""
|
|
|
|
trace = _CURRENT_TRACE.get()
|
|
if trace is None or trace.mode != "audit":
|
|
return
|
|
for frame in reversed(_ACTIVE_SPANS.get()):
|
|
if (
|
|
frame.property_key is not None
|
|
and frame.property_operation == operation
|
|
):
|
|
layer, medium, _unused_operation = frame.property_key.split("|", 2)
|
|
trace._record_cache(
|
|
frame.property_key,
|
|
operation=operation,
|
|
layer=layer,
|
|
medium=medium,
|
|
hits=1 if hit else 0,
|
|
misses=0 if hit else 1,
|
|
)
|
|
return
|
|
|
|
|
|
__all__ = [
|
|
"PROFILE_MODE",
|
|
"PerformanceTrace",
|
|
"performance_span",
|
|
"profile_phase",
|
|
"profile_property",
|
|
"profile_run",
|
|
"record_property_cache",
|
|
"record_property_iterations",
|
|
]
|