pyinstrument is very slow on django tests with docker

[patroqueeet]

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?

[joerick]

Hi @patroqueeet, how are you invoking pyinstrument?

[patroqueeet]

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.

[joerick]

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?

[patroqueeet]

@joerick sure. will go and make a docker image for you to reproduce...

[patroqueeet]

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...

[joerick]

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...

[joerick]

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...

[patroqueeet]

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.

[joerick]

This should now be resolved, using either coarse timers or timing threads on Docker. See the v4.7.0 release notes for info.