File: test_profiler.py

package info (click to toggle)
python-pyinstrument 5.1.1%2Bds-2
  • links: PTS, VCS
  • area: main
  • in suites: forky, sid
  • size: 3,624 kB
  • sloc: python: 6,713; ansic: 897; makefile: 46; sh: 26; javascript: 18
file content (398 lines) | stat: -rw-r--r-- 11,940 bytes parent folder | download
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
import asyncio
import dataclasses
import inspect
import json
import time
from functools import partial
from test.fake_time_util import fake_time
from typing import Generator, Optional

import pytest

from pyinstrument import Profiler, renderers
from pyinstrument.frame import Frame
from pyinstrument.renderers.speedscope import SpeedscopeEvent, SpeedscopeEventType, SpeedscopeFrame
from pyinstrument.session import Session

from .util import assert_never, busy_wait, flaky_in_ci

# Utilities #


def long_function_a():
    time.sleep(0.25)


def long_function_b():
    time.sleep(0.5)


class ClassWithMethods:
    def long_method(self):
        time.sleep(0.25)

    @staticmethod
    def long_static_method():
        time.sleep(0.25)

    @classmethod
    def long_class_method(cls):
        time.sleep(0.25)


# Tests #


def test_collapses_multiple_calls_by_default():
    profiler = Profiler()

    with fake_time():
        profiler.start()

        long_function_a()
        long_function_b()
        long_function_a()
        long_function_b()

        profiler.stop()

    text_output = profiler.output_text()
    print(text_output)

    # output should be something like:
    # 1.500 test_collapses_multiple_calls_by_default  test/test_profiler.py:25
    # |- 0.500 long_function_a  test/test_profiler.py:17
    # |- 0.500 long_function_b  test/test_profiler.py:20

    assert text_output.count("1.500 test_collapses_multiple_calls_by_default") == 1
    assert text_output.count("0.500 long_function_a") == 1
    assert text_output.count("1.000 long_function_b") == 1


def test_profiler_retains_multiple_calls():
    profiler = Profiler()

    with fake_time():
        profiler.start()

        long_function_a()
        long_function_b()
        long_function_a()
        long_function_b()

        profiler.stop()

    print(profiler.output_text())

    assert profiler.last_session
    frame = profiler.last_session.root_frame()
    assert frame
    assert frame.function == "test_profiler_retains_multiple_calls"
    assert len(frame.children) == 4


def test_two_functions():
    profiler = Profiler()

    with fake_time():
        profiler.start()

        long_function_a()
        long_function_b()

        profiler.stop()

    print(profiler.output_text())

    assert profiler.last_session

    frame = profiler.last_session.root_frame()

    assert frame
    assert frame.function == "test_two_functions"
    assert len(frame.children) == 2

    frame_b, frame_a = sorted(frame.children, key=lambda f: f.time, reverse=True)

    assert frame_a.function == "long_function_a"
    assert frame_b.function == "long_function_b"

    # busy CI runners can be slow to wake up from the sleep. So we relax the
    # ranges a bit
    assert frame_a.time == pytest.approx(0.25, abs=0.1)
    assert frame_b.time == pytest.approx(0.5, abs=0.2)


def test_class_methods():
    profiler = Profiler()

    with fake_time():
        profiler.start()

        obj = ClassWithMethods()
        obj.long_method()
        obj.long_class_method()
        obj.long_static_method()
        partial(obj.long_method)()

        profiler.stop()

    text_output = profiler.output_text()
    print(text_output)

    # output should be something like:
    # 1.000 test_class_methods  test/test_profiler.py:124
    # |- 0.500 ClassWithMethods.long_method  test/test_profiler.py:29
    # |  `- 0.500 FakeClock.sleep  test/fake_time_util.py:19
    # |- 0.250 ClassWithMethods.long_class_method  test/test_profiler.py:36
    # |  `- 0.250 FakeClock.sleep  test/fake_time_util.py:19
    # `- 0.250 long_static_method  test/test_profiler.py:32
    #    `- 0.250 FakeClock.sleep  test/fake_time_util.py:19
    assert text_output.count("0.500 ClassWithMethods.long_method") == 1
    assert text_output.count("0.250 ClassWithMethods.long_class_method") == 1
    assert text_output.count("0.250 long_static_method") == 1


def test_context_manager():
    with fake_time():
        with Profiler() as profiler:
            long_function_a()
            long_function_b()

    assert profiler.last_session
    frame = profiler.last_session.root_frame()
    assert frame
    assert frame.function == "test_context_manager"
    assert len(frame.children) == 2


def test_json_output():
    with fake_time():
        with Profiler() as profiler:
            long_function_a()
            long_function_b()

    output_data = profiler.output(renderers.JSONRenderer())

    output = json.loads(output_data)
    assert "root_frame" in output

    root_frame = output["root_frame"]

    assert root_frame["function"] == "test_json_output"
    assert len(root_frame["children"]) == 2


def test_speedscope_output():
    with fake_time():
        with Profiler() as profiler:
            long_function_a()
            long_function_b()

    output_data = profiler.output(renderers.SpeedscopeRenderer())

    output = json.loads(output_data)

    file_level_schema_fields = {
        "$schema",
        "name",
        "exporter",
        "activeProfileIndex",
        "profiles",
        "shared",
    }
    for file_field in file_level_schema_fields:
        assert file_field in output

    assert output["$schema"] == "https://www.speedscope.app/file-format-schema.json"
    assert "pyinstrument" in output["exporter"]
    assert output["activeProfileIndex"] is None
    assert "CPU profile" in output["name"]

    assert "frames" in output["shared"]
    speedscope_frame_list = output["shared"]["frames"]

    # Distinct functions called stores indices in key-value pairs because function
    # index lookup needed for Speedscope event list tests. Were we not testing
    # the event list, the distinct functions called could be stored as a tuple.
    distinct_functions_called = {
        "test_speedscope_output": 0,
        "long_function_a": 1,
        "sleep": 2,
        "long_function_b": 3,
    }
    assert len(speedscope_frame_list) == len(distinct_functions_called)
    speedscope_frame_fields = tuple(field.name for field in dataclasses.fields(SpeedscopeFrame))
    for function_name, frame_index in distinct_functions_called.items():
        for frame_field in speedscope_frame_fields:
            assert frame_field in speedscope_frame_list[frame_index]
        assert speedscope_frame_list[frame_index]["name"] == function_name

    speedscope_profile_list = output["profiles"]
    assert len(speedscope_profile_list) == 1
    speedscope_profile = speedscope_profile_list[0]
    speedscope_profile_fields = ("type", "name", "unit", "startValue", "endValue", "events")
    for profile_field in speedscope_profile_fields:
        assert profile_field in speedscope_profile

    # speedscope_profile["endValue"] is not tested because a fake_time mock
    # timer is used to replace time.time, and this mock causes session.duration
    # to differ from self._event_time just before exiting SpeedscopeRenderer.render
    assert speedscope_profile["type"] == "evented"
    assert speedscope_profile["unit"] == "seconds"
    assert speedscope_profile["startValue"] == 0.0

    output_event_tuple = (
        SpeedscopeEvent(
            SpeedscopeEventType.OPEN,
            0.0,
            distinct_functions_called["test_speedscope_output"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.OPEN,
            0.0,
            distinct_functions_called["long_function_a"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.OPEN,
            0.0,
            distinct_functions_called["sleep"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.CLOSE,
            0.25,
            distinct_functions_called["sleep"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.CLOSE,
            0.25,
            distinct_functions_called["long_function_a"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.OPEN,
            0.25,
            distinct_functions_called["long_function_b"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.OPEN,
            0.25,
            distinct_functions_called["sleep"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.CLOSE,
            0.75,
            distinct_functions_called["sleep"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.CLOSE,
            0.75,
            distinct_functions_called["long_function_b"],
        ),
        SpeedscopeEvent(
            SpeedscopeEventType.CLOSE,
            0.75,
            distinct_functions_called["test_speedscope_output"],
        ),
    )

    speedscope_event_list = speedscope_profile["events"]
    assert len(speedscope_event_list) == len(output_event_tuple)
    speedscope_event_fields = tuple(field.name for field in dataclasses.fields(SpeedscopeEvent))
    for event_index, speedscope_event in enumerate(speedscope_event_list):
        for event_field in speedscope_event_fields:
            assert event_field in speedscope_event

        assert speedscope_event["type"] == output_event_tuple[event_index].type.value
        assert speedscope_event["frame"] == output_event_tuple[event_index].frame
        assert speedscope_event["at"] == pytest.approx(output_event_tuple[event_index].at)


def test_empty_profile():
    with Profiler() as profiler:
        pass
    profiler.output(renderer=renderers.ConsoleRenderer())


@flaky_in_ci
def test_state_management():
    profiler = Profiler()

    assert profiler.last_session is None
    assert profiler.is_running == False

    profiler.start()

    assert profiler.last_session is None
    assert profiler.is_running == True

    busy_wait(0.1)

    profiler.stop()

    assert profiler.is_running == False
    assert profiler.last_session is not None
    assert profiler.last_session.duration == pytest.approx(0.1, rel=0.2)

    # test a second session, does it merge with the first?
    profiler.start()

    assert profiler.is_running == True
    busy_wait(0.1)

    profiler.stop()

    assert profiler.is_running == False

    assert profiler.last_session is not None
    assert profiler.last_session.duration == pytest.approx(0.2, rel=0.2)

    # test a reset
    profiler.reset()
    assert profiler.last_session is None

    # test a reset while running
    profiler.start()
    assert profiler.is_running == True
    profiler.reset()
    assert profiler.is_running == False
    assert profiler.last_session is None


@pytest.mark.parametrize(
    "profiler_method_name,renderer_class",
    [
        ("print", renderers.ConsoleRenderer),
        ("output_text", renderers.ConsoleRenderer),
        ("output_html", renderers.HTMLRenderer),
    ],
)
def test_profiler_convenience_methods_have_all_options_available(
    profiler_method_name, renderer_class
):
    method = getattr(Profiler, profiler_method_name)

    method_signature = inspect.signature(method)
    renderer_signature = inspect.signature(renderer_class)

    for name, parameter in renderer_signature.parameters.items():
        if name == "self":
            continue

        if profiler_method_name == "output_html" and name in {"timeline", "show_all"}:
            # these options have been deprecated
            continue

        assert (
            name in method_signature.parameters
        ), f"Parameter {name} is missing from Profiler.{profiler_method_name}. {parameter}"
        method_parameter = method_signature.parameters[name]

        if profiler_method_name == "print" and name in {"color", "unicode"}:
            # print has a mechanism of autodetecting these
            continue
        assert (
            method_parameter.default == parameter.default
        ), f"Parameter {name} has a different default value in Profiler.{profiler_method_name}. {parameter}"
        assert (
            method_parameter.annotation == parameter.annotation
        ), f"Parameter {name} has a different annotation in Profiler.{profiler_method_name}. {parameter}"