Performance regression on services heavy on logging starting from 6.0.0rc1

[sliwinski-milosz]

Hello!

After updating the pytest version from 5.4.3 to 6.0.0rc1 in my service I noticed the tests performance regression.
I was very determined to find the root cause so I started to run tests on commits that have been added to 6.0.0rc1.

I have been testing it on python:3.9.18-slim-bookworm Docker image.

Pytest 5.4.3->6.0.0rc1 diff

Below you can find the results:

v5.4.3 tests took: 0:03:34 - however on another try they took 4 minutes.

https://github.com/pytest-dev/pytest/commit/e48ac692dedc11e5c5c8722b426f5b575eeadea0 tests took: 0:04:05
https://github.com/pytest-dev/pytest/commit/075903dafa6ef6f62e2af67f336ee45f267feaa1 tests took: 0:05:03 - performance regression
https://github.com/pytest-dev/pytest/commit/43c465c9bf6d40bd579d62e63e883823368e1fde tests took: 0:06:33 - even bigger regression in comparison to previous commit
https://github.com/pytest-dev/pytest/commit/e27228a4e4afc941cac34672400016f59ee1184d tests took: 0:06:23
https://github.com/pytest-dev/pytest/commit/9310d67773433825ba568dba770e7202fe09c916 tests took: 0:08:57
https://github.com/pytest-dev/pytest/commit/d2d11a8bdcd382b0ac1e75af0a36cf826bcc3fa0 tests took: 0:07:34
https://github.com/pytest-dev/pytest/commit/5a6296a2d73d32010d4cddc4dd6cf6a289c01d9d tests took: 0:08:05
https://github.com/pytest-dev/pytest/commit/981b0969404bc4116659dae8fa6318cfbab2c942 tests took: 0:06:54

v7.4.4 tests took: 9:50  - not sure why that long but I'd like to start one step at the time and tackle the regression introduced in old versions first

Unfortunately my tests are not very consistent in terms of execution time and I didn't find an easy way to reproduce the issue that I could provide here. Yet they consistently take ~4mins on pytest==5.4.3 and more than 5 on 6.0.0rc1. I suspect this is somehow related to the fact that my service is logging a lot. I also noticed (but that I am not 100% sure) that on 6.0.0rc1 the tests are getting slower during test execution (by using --durations feature). Meaning that at the beginning they work fast but towards the end they are getting slower.

In the affected commit itself it is mentioned that the performance can be affected. I really hope that you know well the pytest internals and by reading above description you will be able to point the root cause and it will make sense.

Please let me know if you want me to run more tests or provide some logs.

I am sorry that I cannot provide simple way to reproduce this issue.

[sliwinski-milosz]

I found a quicker and more reliable way of testing. Earlier the tests were doing some http calls that were not mocked. Now I run only local tests (unittests) so each run takes almost the same time:

5.4.3                                    - 0:01:13
6.0.0rc1                                 - 0:02:33

075903dafa6ef6f62e2af67f336ee45f267feaa1 - 0:01:40 (first commit affected)
43c465c9bf6d40bd579d62e63e883823368e1fde - 0:01:44
e27228a4e4afc941cac34672400016f59ee1184d - 0:01:42
5814f77455f769d262ee69d209b074d06dc0f8d5 - 0:02:08

I will run more tests if I will have time. For now my conclusions are:
075903d
Above commit is a first one that caused regression. I also can see improvement while reverting that change on latest pytest. If I find some spare time I will open PR with such change.

In the previous message I mentioned that following commit also caused some regression but I wasn't right:
43c465c

There are other commits that were added to 6.0.0rc1 that are causing performance regression but I haven't found yet which ones. Yet with my new method of testing it will take less effort for me to pinpoint them.

[bluetech]

@sliwinski-milosz Do you think you could create a reduced benchmark that you can share? I don't remember all of the details of these commits, but according to the commit messages it seems I did take performance into account so it'd be good to know where the slowness comes. If you can't share, maybe you can run your benchmark in a profiler like cProfile and see the slow stack trace(s).

Which OS and Python versions are you using?

[sliwinski-milosz]

Hello!

I have retested it just to make sure that I am testing now on the same configuration.

Below tests I run in Docker python:3.9.18-slim-bookworm image on MacBook M1.

% docker --version
Docker version 25.0.3, build 4debf41

% docker-compose --version
Docker Compose version v2.24.5-desktop.1

The results:

5.4.3                                    - 0:01:27
6.0.0rc1                                 - 0:02:56
7.4.4                                    - 0:02:55

075903dafa6ef6f62e2af67f336ee45f267feaa1 - 0:01:58 - first commit affected
43c465c9bf6d40bd579d62e63e883823368e1fde - 0:02:01
e27228a4e4afc941cac34672400016f59ee1184d - 0:02:02
8b9b81c3c04399d0ebde8d85a9db60291b325acd - 0:01:57
694fdc655436b6b2eb335d9019002ab81486e4d8 - 0:02:05
fe2febfff21dc9da665f81258525ccee9e2168b7 - 0:02:08
85a06cfafbe49f2c56e22cef4fa88adcf7b54f59 - 0:02:34 - another commit affected
5a6296a2d73d32010d4cddc4dd6cf6a289c01d9d - 0:02:30
4a1557fa0e04132eb847d4a5d01c77f0ab777c5a - 0:02:35
919ac2239d9c0406bf7fdb7231f1380086d218b1 - 0:02:37
5814f77455f769d262ee69d209b074d06dc0f8d5 - 0:02:39
f382a6bb2084c8fb5a4e252ab7f3358752e27f67 - 0:02:33
c8cfff6de5d57c59d7a394f45678386f4d0b5015 - 0:02:42
74f20f9fba3d8990cfbb0cfa9b68062ad97d4f72 - 0:03:05 - another commit affected
64dd7000e52d4220a83cd8197a16b5f2acc1f704 - 0:03:07
9caca5c434a9a63c1e03d12b20ceacb07784f377 - 0:03:02

This time the tests took bit longer so I guess something has changed on my local setup in comparison to my previous runs.
Anyway based on above it is clear which commits introduced the regression.

I also did try to improve it:
main...sliwinski-milosz:pytest:7.4.4dev1
With above change it took: 0:02:31.
The change was applied on top of v7.4.4. Without the change it gives: 0:02:55.

I haven't yet contributed to pytest so I will need more time to find out how to run your tests etc.
If you can help in applying above change, it would be great.