pyinstrument is very slow on django tests with docker
patroqueeet opened this issue · 8 comments
Dear,
I'm trying to use pyinstrument on docker with a django test setup. When I run the command like this ./manage.py test --keepdb services.rest.tests.test_views:AddCompanyTestCase.test_add_company -v 3 I get something like
240.152 <module> manage.py:2
└─ 239.407 execute_from_command_line django/core/management/__init__.py:378
[23227 frames hidden] django, django_nose, nose, unittest, ...
48.646 patched mock/mock.py:1314
└─ 48.625 test_add_company services/rest/tests/test_views.py:59
├─ 21.667 post rest_framework/test.py:296
│ [770 frames hidden] rest_framework, django, reversion, se...
│ 21.055 inner django/core/handlers/exception.py:31
│ └─ 21.055 __call__ company/middleware.py:28
│ └─ 21.036 inner django/core/handlers/exception.py:31
│ └─ 21.036 __call__ project/middleware.py:10
│ └─ 21.036 inner django/core/handlers/exception.py:31
│ [106 frames hidden] django, rest_framework, re, sre_compi...
│ 20.995 dispatch rest_framework/views.py:470
│ └─ 20.982 post services/rest/views.py:813
│ └─ 20.851 save rest_framework/serializers.py:171
│ └─ 20.851 create services/rest/serializers.py:279
│ ├─ 9.561 __get__ django/db/models/fields/related_descriptors.py:373
│ │ [72 frames hidden] django, raven, weakref
│ ├─ 6.187 now django/utils/timezone.py:218
│ │ [2 frames hidden] django
│ └─ 4.289 [self]
├─ 19.563 reverse django/urls/base.py:27
│ [718 frames hidden] django, re, sre_compile, sre_parse, e...
│ 4.988 import_module importlib/__init__.py:109
│ └─ 4.972 <module> project/urls.py:1
└─ 7.285 generate project/generators.py:151
└─ 7.281 _make_user project/generators.py:64
├─ 3.613 _make_username project/generators.py:54
│ └─ 3.612 _make_wordlist project/generators.py:47
│ └─ 3.612 <listcomp> project/generators.py:49
│ └─ 3.602 [self]
└─ 3.368 _make_wordlist project/generators.py:47
└─ 3.368 <listcomp> project/generators.py:49
└─ 3.344 [self]
9.312 load_source imp.py:165
└─ 9.291 <module> services/rest/tests/test_views.py:2
└─ 4.866 <module> services/rest/serializers.py:1
└─ 3.759 <module> dictdiffer/__init__.py:11
[327 frames hidden] dictdiffer, pkg_resources, re, posixp...
40.742 import_module importlib/__init__.py:109
├─ 28.759 <module> shareholder/models.py:1
│ ├─ 22.735 UserProfile shareholder/models.py:1117
│ │ └─ 22.726 __init__ django_languages/fields.py:7
│ │ [11 frames hidden] django_languages, django
│ └─ 2.528 <module> utils/pdf.py:1
│ └─ 2.511 <module> xhtml2pdf/pisa.py:16
│ [1405 frames hidden] xhtml2pdf, reportlab, re, sre_compile...
47.142 import_module importlib/__init__.py:109
└─ 47.118 <module> project/__init__.py:5
├─ 39.173 <module> project/signals.py:4
│ ├─ 25.066 <module> registration/signals.py:1
│ │ [26 frames hidden] registration, django, importlib, path...
│ │ 25.032 import_module importlib/__init__.py:109
│ │ └─ 24.990 <module> project/settings/dev.py:1
│ │ └─ 24.953 <module> project/settings/base.py:12
│ │ ├─ 19.513 <module> project/settings/tests.py:4
│ │ │ └─ 19.512 stack inspect.py:1511
│ │ │ [278 frames hidden] inspect, posixpath, genericpath, cele...
│ │ └─ 4.018 <module> raven/__init__.py:7
│ │ [951 frames hidden] raven, requests, urllib3, re, sre_com...
│ ├─ 8.870 <module> services/slack.py:3
│ │ └─ 8.728 register_task celery/app/base.py:488
│ │ [319 frames hidden] celery, kombu, collections, logging, ...
│ │ 8.552 send celery/utils/dispatch/signal.py:266
│ │ └─ 8.550 setup_periodic_tasks project/celery.py:32
│ │ └─ 8.360 <module> company/tasks.py:9
│ │ └─ 6.836 <module> bs4/__init__.py:18
│ │ [3025 frames hidden] bs4, soupsieve, re, sre_compile, sre_...
│ └─ 5.143 <module> django/contrib/auth/__init__.py:1
│ [2516 frames hidden] django, pathlib, re, sre_compile, sre...
└─ 7.762 <module> project/celery.py:6
└─ 6.292 <module> celery/schedules.py:2
[1914 frames hidden] celery, kombu, importlib_metadata, re...
where even now takes 6s. Without pyinstrument this test takes about ~30s and I need to find out why...
What other information do you need from my side?
Hi @patroqueeet, how are you invoking pyinstrument?
sry for the slight delay :/
in docker I do docker-compose exec app pyinstrument ./manage.py test --keepdb services.rest.tests.test_views:AddCompanyTestCase.test_add_company -v 3./manage.py test --keepdb services -e functional -v 2 --failed
Generally spoken: intention is to identify what slows down my tests... including setUp() etc.
Not sure what's going on here tbh... my tests in Docker seem to work just as normal. Are you able to make a minimal recreation?
@joerick sure. will go and make a docker image for you to reproduce...
Hey, tried with a simple model test on docker and found all working as expected. But the problems come on a large Py3 project.
Hence, closing this until I have some further reproducible truth.
Still: for the records https://stackoverflow.com/questions/62220875/profiling-python-in-a-docker-container-is-very-slow-cprofile-and-pyinstrument more people having this issue...
Thanks for taking another look! If the problem occurs in cProfile too, it's probably at a lower level than we can fix.
A wild guess at the cause would have me thinking about the gettimeofday syscall in pyinstrument_cext - perhaps this is slower in some Docker containers. This article might add some weight to the idea...
I had a thought on this - pyinstrument_cext could add a feature where, rather than calling gettimeofday on every trace event, it checks an internal variable that's being incremented by a thread who is running in a tight loop doing usleep. Perhaps this would be worse performance for systems with vDSO, but it would definitely improve things otherwise...
hey, to be honest, I cannot judge if your wild guess is going in the right direction. if you provide me a branch/PR I can check it out and give you some feedback.