timing.py 11 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405
  1. # -*- coding: utf-8 -*-
  2. """
  3. Timing-Middleware für Performance-Messung.
  4. Misst und protokolliert Event-Verarbeitungszeiten.
  5. """
  6. from __future__ import annotations
  7. import statistics
  8. import time
  9. from collections import defaultdict
  10. from dataclasses import dataclass, field
  11. from datetime import datetime
  12. from typing import TYPE_CHECKING, Any, Callable
  13. from trixy_core.events.middleware.base import (
  14. EventMiddleware,
  15. MiddlewareContext,
  16. MiddlewareResult,
  17. MiddlewareAction,
  18. )
  19. if TYPE_CHECKING:
  20. from trixy_core.events.event_data.base import EventData
  21. @dataclass
  22. class TimingStats:
  23. """
  24. Statistiken für Event-Verarbeitungszeiten.
  25. """
  26. event_name: str
  27. """Name des Events."""
  28. count: int = 0
  29. """Anzahl der Verarbeitungen."""
  30. total_ms: float = 0.0
  31. """Gesamtzeit in Millisekunden."""
  32. min_ms: float = float("inf")
  33. """Minimale Zeit."""
  34. max_ms: float = 0.0
  35. """Maximale Zeit."""
  36. last_ms: float = 0.0
  37. """Letzte Verarbeitungszeit."""
  38. _times: list[float] = field(default_factory=list, repr=False)
  39. """Alle Zeiten für Perzentil-Berechnung."""
  40. @property
  41. def avg_ms(self) -> float:
  42. """Durchschnittliche Zeit in Millisekunden."""
  43. if self.count == 0:
  44. return 0.0
  45. return self.total_ms / self.count
  46. @property
  47. def p50_ms(self) -> float:
  48. """50. Perzentil (Median)."""
  49. if not self._times:
  50. return 0.0
  51. return statistics.median(self._times)
  52. @property
  53. def p90_ms(self) -> float:
  54. """90. Perzentil."""
  55. if not self._times:
  56. return 0.0
  57. return self._get_percentile(90)
  58. @property
  59. def p99_ms(self) -> float:
  60. """99. Perzentil."""
  61. if not self._times:
  62. return 0.0
  63. return self._get_percentile(99)
  64. def _get_percentile(self, percentile: float) -> float:
  65. """
  66. Berechnet ein Perzentil.
  67. Args:
  68. percentile: Perzentil (0-100).
  69. Returns:
  70. Wert am Perzentil.
  71. """
  72. if not self._times:
  73. return 0.0
  74. sorted_times = sorted(self._times)
  75. index = (percentile / 100) * (len(sorted_times) - 1)
  76. lower = int(index)
  77. upper = min(lower + 1, len(sorted_times) - 1)
  78. fraction = index - lower
  79. return sorted_times[lower] * (1 - fraction) + sorted_times[upper] * fraction
  80. def record(self, duration_ms: float) -> None:
  81. """
  82. Zeichnet eine Verarbeitungszeit auf.
  83. Args:
  84. duration_ms: Dauer in Millisekunden.
  85. """
  86. self.count += 1
  87. self.total_ms += duration_ms
  88. self.last_ms = duration_ms
  89. self.min_ms = min(self.min_ms, duration_ms)
  90. self.max_ms = max(self.max_ms, duration_ms)
  91. # Begrenzte Historie für Perzentile
  92. self._times.append(duration_ms)
  93. if len(self._times) > 1000:
  94. self._times = self._times[-500:]
  95. def to_dict(self) -> dict[str, Any]:
  96. """Konvertiert in ein Dictionary."""
  97. return {
  98. "event_name": self.event_name,
  99. "count": self.count,
  100. "total_ms": round(self.total_ms, 2),
  101. "avg_ms": round(self.avg_ms, 2),
  102. "min_ms": round(self.min_ms, 2) if self.min_ms != float("inf") else 0,
  103. "max_ms": round(self.max_ms, 2),
  104. "p50_ms": round(self.p50_ms, 2),
  105. "p90_ms": round(self.p90_ms, 2),
  106. "p99_ms": round(self.p99_ms, 2),
  107. "last_ms": round(self.last_ms, 2),
  108. }
  109. class TimingMiddleware(EventMiddleware):
  110. """
  111. Middleware für Event-Timing-Messungen.
  112. Misst die Verarbeitungszeit jedes Events und sammelt
  113. Statistiken für Performance-Analyse.
  114. Example:
  115. middleware = TimingMiddleware(
  116. slow_threshold_ms=100,
  117. on_slow_event=lambda name, ms: print(f"SLOW: {name} took {ms}ms"),
  118. )
  119. pipeline.add(middleware)
  120. # Später: Statistiken abrufen
  121. stats = middleware.get_stats("my_event")
  122. print(f"Average: {stats.avg_ms}ms")
  123. """
  124. TIMING_KEY = "_timing_start_ns"
  125. def __init__(
  126. self,
  127. name: str = "TimingMiddleware",
  128. enabled: bool = True,
  129. slow_threshold_ms: float = 100.0,
  130. on_slow_event: Callable[[str, float], None] | None = None,
  131. track_all: bool = True,
  132. max_events: int = 1000,
  133. ) -> None:
  134. """
  135. Initialisiert die Timing-Middleware.
  136. Args:
  137. name: Name der Middleware.
  138. enabled: Ob aktiv.
  139. slow_threshold_ms: Schwellenwert für langsame Events (ms).
  140. on_slow_event: Callback für langsame Events (name, duration_ms).
  141. track_all: Ob alle Events erfasst werden.
  142. max_events: Maximale Anzahl erfasster Event-Typen.
  143. """
  144. super().__init__(name, enabled)
  145. self._slow_threshold_ms = slow_threshold_ms
  146. self._on_slow_event = on_slow_event
  147. self._track_all = track_all
  148. self._max_events = max_events
  149. self._stats: dict[str, TimingStats] = {}
  150. self._global_stats = TimingStats(event_name="__global__")
  151. @property
  152. def slow_threshold_ms(self) -> float:
  153. """Schwellenwert für langsame Events."""
  154. return self._slow_threshold_ms
  155. @slow_threshold_ms.setter
  156. def slow_threshold_ms(self, value: float) -> None:
  157. """Setzt den Schwellenwert."""
  158. self._slow_threshold_ms = value
  159. def get_stats(self, event_name: str) -> TimingStats | None:
  160. """
  161. Gibt die Statistiken für ein Event zurück.
  162. Args:
  163. event_name: Name des Events.
  164. Returns:
  165. TimingStats oder None.
  166. """
  167. return self._stats.get(event_name)
  168. def get_all_stats(self) -> dict[str, TimingStats]:
  169. """
  170. Gibt alle Event-Statistiken zurück.
  171. Returns:
  172. Dictionary von Event-Namen zu Statistiken.
  173. """
  174. return dict(self._stats)
  175. def get_global_stats(self) -> TimingStats:
  176. """
  177. Gibt die globalen Statistiken zurück.
  178. Returns:
  179. Globale TimingStats.
  180. """
  181. return self._global_stats
  182. def get_slowest_events(self, n: int = 10) -> list[tuple[str, float]]:
  183. """
  184. Gibt die langsamsten Events zurück.
  185. Args:
  186. n: Anzahl der Events.
  187. Returns:
  188. Liste von (event_name, avg_ms) Tupeln.
  189. """
  190. sorted_events = sorted(
  191. self._stats.items(),
  192. key=lambda x: x[1].avg_ms,
  193. reverse=True,
  194. )
  195. return [(name, stats.avg_ms) for name, stats in sorted_events[:n]]
  196. def reset_stats(self, event_name: str | None = None) -> None:
  197. """
  198. Setzt Statistiken zurück.
  199. Args:
  200. event_name: Spezifisches Event oder None für alle.
  201. """
  202. if event_name:
  203. if event_name in self._stats:
  204. del self._stats[event_name]
  205. else:
  206. self._stats.clear()
  207. self._global_stats = TimingStats(event_name="__global__")
  208. async def before(
  209. self,
  210. context: MiddlewareContext,
  211. ) -> MiddlewareResult:
  212. """
  213. Startet die Zeitmessung.
  214. Args:
  215. context: Der Middleware-Kontext.
  216. Returns:
  217. Ergebnis.
  218. """
  219. # Speichere Startzeit im Kontext
  220. context.set_property(self.TIMING_KEY, time.perf_counter_ns())
  221. return MiddlewareResult()
  222. async def after(
  223. self,
  224. context: MiddlewareContext,
  225. ) -> None:
  226. """
  227. Beendet die Zeitmessung und zeichnet Statistiken auf.
  228. Args:
  229. context: Der Middleware-Kontext.
  230. """
  231. start_ns = context.get_property(self.TIMING_KEY)
  232. if start_ns is None:
  233. return
  234. duration_ns = time.perf_counter_ns() - start_ns
  235. duration_ms = duration_ns / 1_000_000
  236. # Statistiken aktualisieren
  237. if self._track_all:
  238. if context.event_name not in self._stats:
  239. if len(self._stats) < self._max_events:
  240. self._stats[context.event_name] = TimingStats(
  241. event_name=context.event_name
  242. )
  243. if context.event_name in self._stats:
  244. self._stats[context.event_name].record(duration_ms)
  245. self._global_stats.record(duration_ms)
  246. # Slow-Event-Callback
  247. if duration_ms >= self._slow_threshold_ms and self._on_slow_event:
  248. self._on_slow_event(context.event_name, duration_ms)
  249. # Speichere Dauer im Kontext für andere Middlewares
  250. context.set_property("timing_duration_ms", duration_ms)
  251. def to_dict(self) -> dict[str, Any]:
  252. """
  253. Exportiert alle Statistiken als Dictionary.
  254. Returns:
  255. Dictionary mit allen Statistiken.
  256. """
  257. return {
  258. "global": self._global_stats.to_dict(),
  259. "events": {
  260. name: stats.to_dict()
  261. for name, stats in self._stats.items()
  262. },
  263. "slow_threshold_ms": self._slow_threshold_ms,
  264. "slowest_events": self.get_slowest_events(5),
  265. }
  266. class TimeoutMiddleware(EventMiddleware):
  267. """
  268. Middleware für Event-Timeouts.
  269. Bricht Events ab, die zu lange dauern.
  270. Example:
  271. middleware = TimeoutMiddleware(
  272. default_timeout_ms=5000,
  273. per_event_timeouts={"slow_event": 10000},
  274. )
  275. """
  276. def __init__(
  277. self,
  278. name: str = "TimeoutMiddleware",
  279. enabled: bool = True,
  280. default_timeout_ms: float = 5000.0,
  281. per_event_timeouts: dict[str, float] | None = None,
  282. on_timeout: Callable[[str, float], None] | None = None,
  283. ) -> None:
  284. """
  285. Initialisiert die Timeout-Middleware.
  286. Args:
  287. name: Name der Middleware.
  288. enabled: Ob aktiv.
  289. default_timeout_ms: Standard-Timeout in Millisekunden.
  290. per_event_timeouts: Spezifische Timeouts pro Event.
  291. on_timeout: Callback bei Timeout.
  292. """
  293. super().__init__(name, enabled)
  294. self._default_timeout_ms = default_timeout_ms
  295. self._per_event_timeouts = per_event_timeouts or {}
  296. self._on_timeout = on_timeout
  297. def get_timeout(self, event_name: str) -> float:
  298. """
  299. Gibt den Timeout für ein Event zurück.
  300. Args:
  301. event_name: Name des Events.
  302. Returns:
  303. Timeout in Millisekunden.
  304. """
  305. return self._per_event_timeouts.get(event_name, self._default_timeout_ms)
  306. async def before(
  307. self,
  308. context: MiddlewareContext,
  309. ) -> MiddlewareResult:
  310. """Speichert Timeout-Informationen."""
  311. timeout_ms = self.get_timeout(context.event_name)
  312. context.set_property("_timeout_ms", timeout_ms)
  313. context.set_property("_timeout_deadline", time.perf_counter_ns() + (timeout_ms * 1_000_000))
  314. return MiddlewareResult()
  315. async def after(
  316. self,
  317. context: MiddlewareContext,
  318. ) -> None:
  319. """Prüft auf Timeout."""
  320. deadline = context.get_property("_timeout_deadline")
  321. if deadline is None:
  322. return
  323. if time.perf_counter_ns() > deadline:
  324. timeout_ms = context.get_property("_timeout_ms", 0)
  325. if self._on_timeout:
  326. self._on_timeout(context.event_name, context.elapsed_ms)
  327. # Markiere Event als abgebrochen wegen Timeout
  328. context.event_data.metadata["timed_out"] = True
  329. context.event_data.metadata["timeout_ms"] = timeout_ms