Find bottlenecks in your test suites
Big test suites for large projects can be a pain to optimize. pytest-scrutinize
helps you
profile your test runs by exporting detailed timings as JSON for the following things:
All data is associated with the currently executing test or fixture. As an example, you can use this to find all the Django SQL queries executed within a given fixture across your entire test suite.
Install with pip from PyPI
pip install pytest-scrutinize
Run your test suite with the --scrutinize
flag, passing a file path to write to:
pytest --scrutinize=test-timings.jsonl.gz
A tool to help with analysing this data is not included yet, however it can be quickly explored with DuckDB. For example, to find the top 10 fixtures by total duration along with the number of tests that where executed:
select name,
to_microseconds(sum(runtime.as_microseconds)::bigint) as duration,
count(distinct test_id) as test_count
from 'test-timings.jsonl.gz'
where type = 'fixture'
group by all
order by duration desc
limit 10;
Or the tests with the highest number of duplicated SQL queries executed as part of it or any fixture it depends on:
select test_id,
sum(count) as duplicate_queries,
count(distinct sql_hash) as unique_queries,
FROM (SELECT test_id, fixture_name, sql_hash, COUNT(*) AS count
from 'test-timings.jsonl.gz'
where type = 'django-sql'
GROUP BY all
HAVING count > 1)
group by all
order by duplicate_queries desc limit 10;
The resulting file will contain newline-delimited JSON objects. The Pydantic models for these can be found here.
All events captured contain a meta
structure that contains the xdist
worker (if any), the
absolute time the timing was taken and the Python thread name that the timing was captured in.
{
"meta": {
"worker": "gw0",
"recorded_at": "2024-08-17T22:02:44.956924Z",
"thread_id": 3806124,
"thread_name": "MainThread"
}
}
All durations are expressed with the same structure, containing the duration in different formats: nanoseconds, microseconds, ISO 8601 and text
{
"runtime": {
"as_nanoseconds": 60708,
"as_microseconds": 60,
"as_iso": "PT0.00006S",
"as_text": "60 microseconds"
}
}
Pytest fixtures can be simple functions, or context managers that can clean up resources after a
test has finished. pytest-scrutinize
records both the setup and teardown times for all fixtures,
allowing you to precisely locate performance bottlenecks:
@pytest.fixture
def slow_teardown():
yield
time.sleep(1)
{
"meta": {
"worker": "master",
"recorded_at": "2024-08-17T21:23:54.736177Z",
"thread_name": "MainThread"
},
"type": "fixture",
"name": "pytest_django.plugin._django_set_urlconf",
"short_name": "_django_set_urlconf",
"test_id": "tests/test_plugin.py::test_all[normal]",
"scope": "function",
"setup": {
"as_nanoseconds": 5792,
"as_microseconds": 5,
"as_iso": "PT0.000005S",
"as_text": "5 microseconds"
},
"teardown": {
"as_nanoseconds": 2167,
"as_microseconds": 2,
"as_iso": "PT0.000002S",
"as_text": "2 microseconds"
},
"runtime": {
"as_nanoseconds": 7959,
"as_microseconds": 7,
"as_iso": "PT0.000007S",
"as_text": "7 microseconds"
}
}
Information on Django SQL queries can be captured with the --scrutinize-django-sql
flag. By
default, the hash of the SQL query is captured (allowing you to count duplicate queries), but
the raw SQL can also be captured:
# Log the hashes of the executed SQL queries
pytest --scrutinize=test-timings.jsonl.gz --scrutinize-django-sql
# Log raw SQL queries. Warning: May produce very large files!
pytest --scrutinize=test-timings.jsonl.gz --scrutinize-django-sql=query
{
"meta": {
"worker": "master",
"recorded_at": "2024-08-17T22:02:47.218492Z",
"thread_name": "MainThread"
},
"name": "django_sql",
"test_id": "test_django.py::test_case",
"fixture_name": "test_django.teardown_fixture",
"runtime": {
"as_nanoseconds": 18375,
"as_microseconds": 18,
"as_iso": "PT0.000018S",
"as_text": "18 microseconds"
},
"type": "django-sql",
"sql_hash": "be0beb84a58eab3bdc1fc4214f90abe9e937e5cc7f54008e02ab81d51533bc16",
"sql": "INSERT INTO \"django_app_dummymodel\" (\"foo\") VALUES (%s) RETURNING \"django_app_dummymodel\".\"id\""
}
Any arbitrary Python function can be captured by passing a comma-separated string of paths to
--scrutinize-func
:
# Record all boto3 clients that are created, along with their timings:
pytest --scrutinize=test-timings.jsonl.gz --scrutinize-func=botocore.session.Session.create_client
{
"meta": {
"worker": "gw0",
"recorded_at": "2024-08-17T22:02:44.296938Z",
"thread_name": "MainThread"
},
"name": "urllib.parse.parse_qs",
"test_id": "test_mock.py::test_case",
"fixture_name": "test_mock.teardown_fixture",
"runtime": {
"as_nanoseconds": 2916,
"as_microseconds": 2,
"as_iso": "PT0.000002S",
"as_text": "2 microseconds"
},
"type": "mock"
}
Garbage collection events can be captured with the --scrutinize-gc
flag. Every GC is captured,
along with the total time and number of objects collected. This can be used to find tests that
generate significant GC pressure by creating lots of circular-referenced objects:
pytest --scrutinize=test-timings.jsonl.gz --scrutinize-gc
{
"meta": {
"worker": "gw0",
"recorded_at": "2024-08-17T22:02:44.962665Z",
"thread_name": "MainThread"
},
"type": "gc",
"runtime": {
"as_nanoseconds": 5404333,
"as_microseconds": 5404,
"as_iso": "PT0.005404S",
"as_text": "5404 microseconds"
},
"collected_count": 279,
"generation": 2
}