Repository navigation
Performance regression with Django #1721
Description
How do you use Sentry?
Sentry Saas (sentry.io)
Version
1.10.1
Steps to Reproduce
Updating from 1.9.8 to 1.10.1 has introduced a huge performance regression which seems to be related to django template processing.
One test case (run with profiling using cProfile) went from 22 seconds to 19 minutes 18 seconds.
Python 3.9
Django 2.2.
sentry-sdk 1.9.8 / 1.10.1
pytest 7.2.0
pytest-django 4.5.2
coverage 6.5.0
The only library that changes version between the two tests is sentry-sdk.
Profiling reveals a huge number of additional function calls - approximately 7x as many as in sentry-sdk 1.9.8.
I've included snakeviz heatmaps of the profiling results drilled down to the test case to show where the time is being spent. I'd rather not directly put the .prof files up here.
Expected Result
With the older sentry-sdk==1.9.8
pytest -m "not functional" --junitxml=qa_reports/junit/unit-tests.xml --reuse-db --profile --profile-svg tests/unit/portal/test_ip_blocked.py::LoginTestCase::test_login_from_NOT_BLOCKED_IP_SUCCEEDS
===================================== test session starts =====================================
platform linux -- Python 3.9.15, pytest-7.2.0, pluggy-1.0.0 -- /venv/bin/python
cachedir: .pytest_cache
django: settings: project.settings (from option)
rootdir: /app, configfile: pyproject.toml
plugins: celery-4.3.1, forked-1.4.0, mock-3.10.0, profiling-1.7.0, requests-mock-1.10.0, cov-4.0.0, xdist-2.5.0, django-4.5.2
collected 1 item
tests/unit/portal/test_ip_blocked.py::LoginTestCase::test_login_from_NOT_BLOCKED_IP_SUCCEEDS PASSED [100%]
------------------ generated xml file: /app/qa_reports/junit/unit-tests.xml -------------------
Profiling (from /app/prof/combined.prof):
Thu Nov 3 17:43:40 2022 /app/prof/combined.prof
5797777 function calls (5687652 primitive calls) in 7.768 seconds
Ordered by: cumulative time
List reduced from 5819 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 7.783 7.783 runner.py:109(pytest_runtest_protocol)
1 0.000 0.000 7.782 7.782 runner.py:117(runtestprotocol)
3 0.000 0.000 7.782 2.594 runner.py:217(call_and_report)
78/11 0.000 0.000 7.782 0.707 _hooks.py:244(__call__)
78/11 0.000 0.000 7.782 0.707 _manager.py:77(_hookexec)
78/11 0.001 0.000 7.782 0.707 _callers.py:9(_multicall)
3 0.000 0.000 7.743 2.581 runner.py:245(call_runtest_hook)
3 0.000 0.000 7.743 2.581 runner.py:316(from_call)
3 0.000 0.000 7.743 2.581 runner.py:260(<lambda>)
1 0.000 0.000 5.482 5.482 runner.py:158(pytest_runtest_call)
1 0.000 0.000 5.482 5.482 plugin.py:484(non_debugging_runtest)
1 0.000 0.000 5.482 5.482 testcases.py:253(__call__)
1 0.000 0.000 5.480 5.480 case.py:650(__call__)
1 0.000 0.000 5.480 5.480 case.py:558(run)
1 0.000 0.000 5.220 5.220 case.py:549(_callTestMethod)
1 0.000 0.000 5.220 5.220 test_ip_blocked.py:79(test_login_from_NOT_BLOCKED_IP_SUCCEEDS)
1 0.000 0.000 5.218 5.218 util.py:183(login_with_ip)
2 0.000 0.000 4.203 2.101 client.py:540(post)
4 0.000 0.000 4.202 1.051 client.py:398(generic)
4 0.000 0.000 4.202 1.051 client.py:465(request)
SVG profile in /app/prof/combined.svg.
===================================== 1 passed in 22.70s ======================================
Actual Result
With sentry-sdk==1.10.1
pytest -m "not functional" --junitxml=qa_reports/junit/unit-tests.xml --reuse-db --profile --profile-svg tests/unit/portal/test_ip_blocked.py::LoginTestCase::test_login_from_NOT_BLOCKED_IP_SUCCEEDS
===================================== test session starts =====================================
platform linux -- Python 3.9.15, pytest-7.2.0, pluggy-1.0.0 -- /venv/bin/python
cachedir: .pytest_cache
django: settings: project.settings (from option)
rootdir: /app, configfile: pyproject.toml
plugins: celery-4.3.1, forked-1.4.0, mock-3.10.0, profiling-1.7.0, requests-mock-1.10.0, cov-4.0.0, xdist-2.5.0, django-4.5.2
collected 1 item
tests/unit/portal/test_ip_blocked.py::LoginTestCase::test_login_from_NOT_BLOCKED_IP_SUCCEEDS PASSED [100%]
------------------ generated xml file: /app/qa_reports/junit/unit-tests.xml -------------------
Profiling (from /app/prof/combined.prof):
Thu Nov 3 17:41:22 2022 /app/prof/combined.prof
40227283 function calls (38736169 primitive calls) in 1147.050 seconds
Ordered by: cumulative time
List reduced from 6140 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 1147.097 1147.097 runner.py:109(pytest_runtest_protocol)
1 0.000 0.000 1147.095 1147.095 runner.py:117(runtestprotocol)
3 0.000 0.000 1147.095 382.365 runner.py:217(call_and_report)
78/11 0.001 0.000 1147.095 104.281 _hooks.py:244(__call__)
78/11 0.000 0.000 1147.095 104.281 _manager.py:77(_hookexec)
78/11 0.002 0.000 1147.095 104.281 _callers.py:9(_multicall)
3 0.000 0.000 1147.038 382.346 runner.py:245(call_runtest_hook)
3 0.000 0.000 1147.038 382.346 runner.py:316(from_call)
3 0.000 0.000 1147.038 382.346 runner.py:260(<lambda>)
1 0.000 0.000 1088.183 1088.183 runner.py:158(pytest_runtest_call)
1 0.000 0.000 1088.183 1088.183 plugin.py:484(non_debugging_runtest)
1 0.000 0.000 1088.183 1088.183 testcases.py:253(__call__)
1 0.000 0.000 1088.180 1088.180 case.py:650(__call__)
1 0.000 0.000 1088.180 1088.180 case.py:558(run)
1 0.000 0.000 1087.772 1087.772 case.py:549(_callTestMethod)
1 0.000 0.000 1087.772 1087.772 test_ip_blocked.py:79(test_login_from_NOT_BLOCKED_IP_SUCCEEDS)
1 0.000 0.000 1087.768 1087.768 util.py:183(login_with_ip)
2 0.000 0.000 1085.937 542.968 client.py:540(post)
4 0.000 0.000 1085.936 271.484 client.py:398(generic)
4 0.000 0.000 1085.936 271.484 client.py:465(request)
===================================== test session starts =====================================
platform linux -- Python 3.9.15, pytest-7.2.0, pluggy-1.0.0 -- /venv/bin/python
cachedir: .pytest_cache
django: settings: project.settings (from option)
rootdir: /app, configfile: pyproject.toml
plugins: celery-4.3.1, forked-1.4.0, mock-3.10.0, profiling-1.7.0, requests-mock-1.10.0, cov-4.0.0, xdist-2.5.0, django-4.5.2
collected 1 item
tests/unit/portal/test_ip_blocked.py::LoginTestCase::test_login_from_NOT_BLOCKED_IP_SUCCEEDS PASSED [100%]
------------------ generated xml file: /app/qa_reports/junit/unit-tests.xml -------------------
Profiling (from /app/prof/combined.prof):
Thu Nov 3 18:06:15 2022 /app/prof/combined.prof
15277656 function calls (14530273 primitive calls) in 843.015 seconds
Ordered by: cumulative time
List reduced from 5837 to 20 due to restriction <20>
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 843.036 843.036 runner.py:109(pytest_runtest_protocol)
1 0.000 0.000 843.036 843.036 runner.py:117(runtestprotocol)
3 0.000 0.000 843.035 281.012 runner.py:217(call_and_report)
78/11 0.000 0.000 843.035 76.640 _hooks.py:244(__call__)
78/11 0.000 0.000 843.035 76.640 _manager.py:77(_hookexec)
78/11 0.001 0.000 843.035 76.640 _callers.py:9(_multicall)
3 0.000 0.000 842.986 280.995 runner.py:245(call_runtest_hook)
3 0.000 0.000 842.986 280.995 runner.py:316(from_call)
3 0.000 0.000 842.986 280.995 runner.py:260(<lambda>)
1 0.000 0.000 839.899 839.899 runner.py:158(pytest_runtest_call)
1 0.000 0.000 839.899 839.899 plugin.py:484(non_debugging_runtest)
1 0.000 0.000 839.899 839.899 testcases.py:253(__call__)
1 0.000 0.000 839.896 839.896 case.py:650(__call__)
1 0.000 0.000 839.896 839.896 case.py:558(run)
1 0.000 0.000 839.503 839.503 case.py:549(_callTestMethod)
1 0.000 0.000 839.503 839.503 test_ip_blocked.py:79(test_login_from_NOT_BLOCKED_IP_SUCCEEDS)
1 0.000 0.000 839.499 839.499 util.py:183(login_with_ip)
2 0.000 0.000 838.172 419.086 client.py:540(post)
4 0.000 0.000 838.172 209.543 client.py:398(generic)
4 0.000 0.000 838.171 209.543 client.py:465(request)
SVG profile in /app/prof/combined.svg.
================================ 1 passed in 852.46s (0:14:12) ================================
Reacted by kid-alan and Daniel Inniss
Activity
tevansuk commentedon Nov 3, 2022
I think this is the culprit:
antonpirker commentedon Nov 4, 2022
Hello @tevansuk
Thanks for reporting this and the great profiling work.
We added instrumentation for Django signals to see in our performance view all the signals that where processed and how long they took.
This is the problematic code: https://github.com/getsentry/sentry-python/blob/master/sentry_sdk/integrations/django/signals_handlers.py#L17-L34
So the
str(receiver)is probably the part that takes very long.I will look into this later today!
antonpirker commentedon Nov 4, 2022
I have now optimized the function in question: #1725
Do you have any chance to test the branch to see if it improves your situation @tevansuk
tevansuk commentedon Nov 4, 2022
Thanks for looking in to this @antonpirker - yes, this is significantly better:
Very similar to the 1.9.8 heatmap.
I also had a chance to look in to why we are affected by it - our use of signals is nothing special, but we are using the
@receiverdecorator rather thanSignal.connect, and in a few cases we have code like:Sadly, changing this to
Signal.connectinstead had no effect (apart from probably getting a better name for the signal handler on the stacked handler!) - I guess whatever weirdness is in a handler added by one of the libraries we use - more digging required on my part!antonpirker commentedon Nov 4, 2022
Ok, so we will include this fix in the next release (which should happen beginning of next week)
antonpirker commentedon Jul 25, 2023
This should be done.