timing.py 12 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427
  1. # -*- coding: utf-8 -*-
  2. """
  3. Timing-Decorators für Performance-Messung.
  4. Bietet @timed für einfache Zeitmessung und @profile für
  5. detailliertes Profiling von Funktionen.
  6. """
  7. from __future__ import annotations
  8. import asyncio
  9. import functools
  10. import time
  11. from dataclasses import dataclass, field
  12. from datetime import datetime
  13. from typing import Any, Callable, ParamSpec, TypeVar
  14. P = ParamSpec("P")
  15. R = TypeVar("R")
  16. @dataclass
  17. class TimingResult:
  18. """
  19. Ergebnis einer Zeitmessung.
  20. Enthält alle relevanten Timing-Informationen für eine
  21. Funktionsausführung.
  22. """
  23. function_name: str
  24. duration_seconds: float
  25. start_time: datetime
  26. end_time: datetime
  27. args_count: int = 0
  28. kwargs_count: int = 0
  29. success: bool = True
  30. error: str | None = None
  31. @property
  32. def duration_ms(self) -> float:
  33. """Gibt die Dauer in Millisekunden zurück."""
  34. return self.duration_seconds * 1000
  35. def to_dict(self) -> dict[str, Any]:
  36. """Konvertiert das Ergebnis in ein Dictionary."""
  37. return {
  38. "function": self.function_name,
  39. "duration_seconds": self.duration_seconds,
  40. "duration_ms": self.duration_ms,
  41. "start_time": self.start_time.isoformat(),
  42. "end_time": self.end_time.isoformat(),
  43. "success": self.success,
  44. "error": self.error,
  45. }
  46. @dataclass
  47. class ProfilingStats:
  48. """
  49. Aggregierte Profiling-Statistiken für eine Funktion.
  50. Sammelt Statistiken über mehrere Aufrufe hinweg.
  51. """
  52. function_name: str
  53. call_count: int = 0
  54. total_time: float = 0.0
  55. min_time: float = float("inf")
  56. max_time: float = 0.0
  57. error_count: int = 0
  58. last_call: datetime | None = None
  59. _times: list[float] = field(default_factory=list)
  60. @property
  61. def avg_time(self) -> float:
  62. """Durchschnittliche Ausführungszeit."""
  63. return self.total_time / self.call_count if self.call_count > 0 else 0.0
  64. @property
  65. def success_rate(self) -> float:
  66. """Erfolgsrate in Prozent."""
  67. if self.call_count == 0:
  68. return 100.0
  69. return ((self.call_count - self.error_count) / self.call_count) * 100
  70. def record(self, duration: float, success: bool = True) -> None:
  71. """
  72. Zeichnet eine Ausführung auf.
  73. Args:
  74. duration: Dauer in Sekunden.
  75. success: Ob die Ausführung erfolgreich war.
  76. """
  77. self.call_count += 1
  78. self.total_time += duration
  79. self.min_time = min(self.min_time, duration)
  80. self.max_time = max(self.max_time, duration)
  81. self.last_call = datetime.now()
  82. if not success:
  83. self.error_count += 1
  84. # Für Percentil-Berechnung (limitiert auf letzte 1000 Werte)
  85. self._times.append(duration)
  86. if len(self._times) > 1000:
  87. self._times.pop(0)
  88. def percentile(self, p: float) -> float:
  89. """
  90. Berechnet das p-te Percentil der Ausführungszeiten.
  91. Args:
  92. p: Percentil zwischen 0 und 100.
  93. Returns:
  94. Percentil-Wert in Sekunden.
  95. """
  96. if not self._times:
  97. return 0.0
  98. sorted_times = sorted(self._times)
  99. index = int((p / 100) * len(sorted_times))
  100. index = min(index, len(sorted_times) - 1)
  101. return sorted_times[index]
  102. def reset(self) -> None:
  103. """Setzt alle Statistiken zurück."""
  104. self.call_count = 0
  105. self.total_time = 0.0
  106. self.min_time = float("inf")
  107. self.max_time = 0.0
  108. self.error_count = 0
  109. self.last_call = None
  110. self._times.clear()
  111. def to_dict(self) -> dict[str, Any]:
  112. """Konvertiert die Statistiken in ein Dictionary."""
  113. return {
  114. "function": self.function_name,
  115. "call_count": self.call_count,
  116. "total_time_seconds": self.total_time,
  117. "avg_time_seconds": self.avg_time,
  118. "min_time_seconds": self.min_time if self.min_time != float("inf") else 0,
  119. "max_time_seconds": self.max_time,
  120. "p50_seconds": self.percentile(50),
  121. "p95_seconds": self.percentile(95),
  122. "p99_seconds": self.percentile(99),
  123. "error_count": self.error_count,
  124. "success_rate": self.success_rate,
  125. "last_call": self.last_call.isoformat() if self.last_call else None,
  126. }
  127. # Globaler Speicher für Profiling-Statistiken
  128. _profiling_stats: dict[str, ProfilingStats] = {}
  129. def get_profiling_stats(function_name: str | None = None) -> dict[str, ProfilingStats]:
  130. """
  131. Gibt Profiling-Statistiken zurück.
  132. Args:
  133. function_name: Optional spezifischer Funktionsname.
  134. Returns:
  135. Dictionary mit Statistiken.
  136. """
  137. if function_name:
  138. if function_name in _profiling_stats:
  139. return {function_name: _profiling_stats[function_name]}
  140. return {}
  141. return dict(_profiling_stats)
  142. def reset_profiling_stats(function_name: str | None = None) -> None:
  143. """
  144. Setzt Profiling-Statistiken zurück.
  145. Args:
  146. function_name: Optional spezifischer Funktionsname.
  147. """
  148. if function_name:
  149. if function_name in _profiling_stats:
  150. _profiling_stats[function_name].reset()
  151. else:
  152. _profiling_stats.clear()
  153. def timed(
  154. callback: Callable[[TimingResult], None] | None = None,
  155. log_args: bool = False,
  156. ) -> Callable[[Callable[P, R]], Callable[P, R]]:
  157. """
  158. Decorator zur Zeitmessung einer Funktion.
  159. Misst die Ausführungszeit und ruft optional einen Callback
  160. mit dem Ergebnis auf.
  161. Args:
  162. callback: Optionale Funktion, die mit TimingResult aufgerufen wird.
  163. log_args: Ob Argument-Anzahl mitgeloggt werden soll.
  164. Returns:
  165. Decorator-Funktion.
  166. Example:
  167. @timed()
  168. def slow_function():
  169. time.sleep(1)
  170. @timed(callback=lambda r: print(f"Took {r.duration_ms}ms"))
  171. def another_function():
  172. pass
  173. """
  174. def decorator(func: Callable[P, R]) -> Callable[P, R]:
  175. @functools.wraps(func)
  176. def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
  177. start_time = datetime.now()
  178. start = time.perf_counter()
  179. error_msg = None
  180. success = True
  181. try:
  182. result = func(*args, **kwargs)
  183. return result
  184. except Exception as e:
  185. success = False
  186. error_msg = str(e)
  187. raise
  188. finally:
  189. end = time.perf_counter()
  190. end_time = datetime.now()
  191. duration = end - start
  192. timing_result = TimingResult(
  193. function_name=func.__qualname__,
  194. duration_seconds=duration,
  195. start_time=start_time,
  196. end_time=end_time,
  197. args_count=len(args) if log_args else 0,
  198. kwargs_count=len(kwargs) if log_args else 0,
  199. success=success,
  200. error=error_msg,
  201. )
  202. if callback:
  203. callback(timing_result)
  204. return wrapper
  205. return decorator
  206. def async_timed(
  207. callback: Callable[[TimingResult], None] | None = None,
  208. log_args: bool = False,
  209. ) -> Callable[[Callable[P, R]], Callable[P, R]]:
  210. """
  211. Async-Decorator zur Zeitmessung.
  212. Wie @timed, aber für async Funktionen.
  213. Args:
  214. callback: Optionale Funktion, die mit TimingResult aufgerufen wird.
  215. log_args: Ob Argument-Anzahl mitgeloggt werden soll.
  216. Returns:
  217. Decorator-Funktion.
  218. Example:
  219. @async_timed()
  220. async def slow_async_function():
  221. await asyncio.sleep(1)
  222. """
  223. def decorator(func: Callable[P, R]) -> Callable[P, R]:
  224. @functools.wraps(func)
  225. async def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
  226. start_time = datetime.now()
  227. start = time.perf_counter()
  228. error_msg = None
  229. success = True
  230. try:
  231. result = await func(*args, **kwargs)
  232. return result
  233. except Exception as e:
  234. success = False
  235. error_msg = str(e)
  236. raise
  237. finally:
  238. end = time.perf_counter()
  239. end_time = datetime.now()
  240. duration = end - start
  241. timing_result = TimingResult(
  242. function_name=func.__qualname__,
  243. duration_seconds=duration,
  244. start_time=start_time,
  245. end_time=end_time,
  246. args_count=len(args) if log_args else 0,
  247. kwargs_count=len(kwargs) if log_args else 0,
  248. success=success,
  249. error=error_msg,
  250. )
  251. if callback:
  252. callback(timing_result)
  253. return wrapper
  254. return decorator
  255. def profile(
  256. name: str | None = None,
  257. threshold_seconds: float | None = None,
  258. callback: Callable[[ProfilingStats], None] | None = None,
  259. ) -> Callable[[Callable[P, R]], Callable[P, R]]:
  260. """
  261. Decorator für detailliertes Profiling.
  262. Sammelt Statistiken über mehrere Aufrufe hinweg.
  263. Args:
  264. name: Optionaler Name für die Statistiken (Default: Funktionsname).
  265. threshold_seconds: Optionaler Schwellenwert für Warnungen.
  266. callback: Optionaler Callback bei Schwellenwert-Überschreitung.
  267. Returns:
  268. Decorator-Funktion.
  269. Example:
  270. @profile(threshold_seconds=1.0)
  271. def database_query():
  272. # Langsame Abfrage
  273. pass
  274. # Statistiken abrufen
  275. stats = get_profiling_stats("database_query")
  276. """
  277. def decorator(func: Callable[P, R]) -> Callable[P, R]:
  278. stats_name = name or func.__qualname__
  279. # Statistik-Objekt erstellen falls nicht vorhanden
  280. if stats_name not in _profiling_stats:
  281. _profiling_stats[stats_name] = ProfilingStats(function_name=stats_name)
  282. stats = _profiling_stats[stats_name]
  283. @functools.wraps(func)
  284. def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
  285. start = time.perf_counter()
  286. success = True
  287. try:
  288. result = func(*args, **kwargs)
  289. return result
  290. except Exception:
  291. success = False
  292. raise
  293. finally:
  294. duration = time.perf_counter() - start
  295. stats.record(duration, success)
  296. # Schwellenwert-Prüfung
  297. if threshold_seconds and duration > threshold_seconds:
  298. if callback:
  299. callback(stats)
  300. # Statistik-Zugriff über die Funktion ermöglichen
  301. wrapper.stats = stats # type: ignore
  302. wrapper.reset_stats = stats.reset # type: ignore
  303. return wrapper
  304. return decorator
  305. def async_profile(
  306. name: str | None = None,
  307. threshold_seconds: float | None = None,
  308. callback: Callable[[ProfilingStats], None] | None = None,
  309. ) -> Callable[[Callable[P, R]], Callable[P, R]]:
  310. """
  311. Async-Decorator für detailliertes Profiling.
  312. Args:
  313. name: Optionaler Name für die Statistiken.
  314. threshold_seconds: Optionaler Schwellenwert für Warnungen.
  315. callback: Optionaler Callback bei Schwellenwert-Überschreitung.
  316. Returns:
  317. Decorator-Funktion.
  318. """
  319. def decorator(func: Callable[P, R]) -> Callable[P, R]:
  320. stats_name = name or func.__qualname__
  321. if stats_name not in _profiling_stats:
  322. _profiling_stats[stats_name] = ProfilingStats(function_name=stats_name)
  323. stats = _profiling_stats[stats_name]
  324. @functools.wraps(func)
  325. async def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
  326. start = time.perf_counter()
  327. success = True
  328. try:
  329. result = await func(*args, **kwargs)
  330. return result
  331. except Exception:
  332. success = False
  333. raise
  334. finally:
  335. duration = time.perf_counter() - start
  336. stats.record(duration, success)
  337. if threshold_seconds and duration > threshold_seconds:
  338. if callback:
  339. callback(stats)
  340. wrapper.stats = stats # type: ignore
  341. wrapper.reset_stats = stats.reset # type: ignore
  342. return wrapper
  343. return decorator