1"""
2Where a run's time went.
3
4A run is mostly not tests. Before the first test the app is set up, its
5packages are imported, the test files are read and the database is made,
6and after the last test it is dropped. One test of 20 milliseconds is a run
7of more than a second, and "1 passed in 0.02s" would not say where the rest
8went. So the runner keeps the time each phase took, in the order they
9happen, and the report says when they came to more than the tests did.
10
11The clock starts when `plain.runtime` was imported, which is the first thing
12a `plain` command does. What came before it, the interpreter starting and
13Python's own imports, a process can't time: the nearest it has is the CPU
14time it had used by then, and that is what the first phase holds, and says.
15"""
16
17import time
18from dataclasses import dataclass
19from typing import TYPE_CHECKING
20
21from plain.runtime import CPU_SECONDS_BEFORE_PLAIN, PLAIN_IMPORTED_AT
22
23if TYPE_CHECKING:
24 from .execution import TestRun
25
26__all__ = []
27
28# A package whose import took this long, or a setup hook that did, gets a
29# line of its own under the runtime setup phase. The rest share one. A slow
30# import is the one cost an app can cut itself.
31SLOW_PART_SECONDS = 0.05
32
33
34@dataclass(frozen=True, kw_only=True)
35class Part:
36 """One thing inside a phase that is worth a line: `import app.agents`."""
37
38 name: str
39 seconds: float
40 # What a lifecycle says its setup spent the time on (`describe_setup`):
41 # `built template (49 migrations)` under `PostgresTestLifecycle`.
42 parts: tuple[Part, ...] = ()
43
44
45@dataclass(frozen=True, kw_only=True)
46class Phase:
47 # "python_startup", "command", "runtime_setup", "helper_modules",
48 # "lifecycles_loaded", "collection", "lifecycle_setup", "tests",
49 # "lifecycle_teardown", "report", then "unaccounted".
50 name: str
51 seconds: float
52 # "wall" for the time from the phase's start to its end. "cpu" for
53 # "python_startup", which is the CPU time the process had used before
54 # the clock could start.
55 measured: str = "wall"
56 parts: tuple[Part, ...] = ()
57
58
59class RunTimeline:
60 """
61 Marks the end of each phase as the run reaches it, and gives the phases
62 back with what the marks don't account for as a phase of its own.
63 """
64
65 def __init__(self) -> None:
66 self._started_at = PLAIN_IMPORTED_AT
67 self._last_mark = self._started_at
68 self._phases: list[Phase] = []
69
70 def phase_ended(self, name: str, *, parts: tuple[Part, ...] = ()) -> None:
71 now = time.perf_counter()
72 self._phases.append(
73 Phase(name=name, seconds=now - self._last_mark, parts=parts)
74 )
75 self._last_mark = now
76
77 def run_ended(self, run: TestRun) -> None:
78 """
79 The run's own phases, which it timed itself: setting the lifecycles
80 up, the tests, and taking the lifecycles down. What the run took
81 beyond those three is left for "unaccounted".
82 """
83 self._phases.append(
84 Phase(
85 name="lifecycle_setup",
86 seconds=sum((part.seconds for part in run.lifecycle_setup), 0.0),
87 parts=run.lifecycle_setup,
88 )
89 )
90 self._phases.append(Phase(name="tests", seconds=run.tests_seconds))
91 self._phases.append(
92 Phase(
93 name="lifecycle_teardown",
94 seconds=sum((part.seconds for part in run.lifecycle_teardown), 0.0),
95 parts=run.lifecycle_teardown,
96 )
97 )
98 self._last_mark = time.perf_counter()
99
100 def phases(self) -> tuple[Phase, ...]:
101 """
102 Every phase so far: Python starting first, and last what the marks
103 don't account for, so that the wall-clock phases add up to the time
104 from the first Plain import to the last mark.
105 """
106 elapsed = self._last_mark - self._started_at
107 accounted = sum((phase.seconds for phase in self._phases), 0.0)
108 return (
109 Phase(
110 name="python_startup",
111 seconds=CPU_SECONDS_BEFORE_PLAIN,
112 measured="cpu",
113 ),
114 *self._phases,
115 Phase(name="unaccounted", seconds=max(elapsed - accounted, 0.0)),
116 )
117
118
119def seconds_in_all(phases: tuple[Phase, ...]) -> float:
120 """The run from Python starting to the report, as near as is known."""
121 return sum((phase.seconds for phase in phases), 0.0)
122
123
124def seconds_outside_the_tests(phases: tuple[Phase, ...]) -> float:
125 return sum((phase.seconds for phase in phases if phase.name != "tests"), 0.0)
126
127
128def runtime_setup_parts() -> tuple[Part, ...]:
129 """
130 What `plain.runtime.setup()` spent its time on, from what it recorded:
131 the setup hooks, the settings, the packages' imports, and the packages'
132 `ready()` methods. A slow hook or import has a line of its own. Nothing
133 when the runtime wasn't set up (library mode).
134 """
135 from plain.runtime import setup_timing
136
137 if setup_timing is None:
138 return ()
139
140 return (
141 *_slow_ones_and_the_rest(setup_timing.hooks, each="hook", rest="hooks"),
142 Part(name="settings", seconds=setup_timing.settings),
143 *_slow_ones_and_the_rest(
144 setup_timing.package_imports, each="import", rest="imports"
145 ),
146 Part(name="ready()", seconds=setup_timing.ready),
147 )
148
149
150def _slow_ones_and_the_rest(
151 timed: tuple[tuple[str, float], ...], *, each: str, rest: str
152) -> tuple[Part, ...]:
153 """
154 `import app.agents` for each one that was slow, then `other imports (24)`
155 for the rest together, or `imports (25)` when none was slow.
156 """
157 slow = [(name, seconds) for name, seconds in timed if seconds >= SLOW_PART_SECONDS]
158 parts = [Part(name=f"{each} {name}", seconds=seconds) for name, seconds in slow]
159 others = len(timed) - len(slow)
160 if others:
161 what = f"other {rest}" if slow else rest
162 seconds = sum(seconds for _, seconds in timed) - sum(
163 seconds for _, seconds in slow
164 )
165 parts.append(Part(name=f"{what} ({others})", seconds=seconds))
166 return tuple(parts)