PHPUnit tests almost 300% slower after Symfony update

[kobelobster]

Q	A
Bug report?	yes
Feature request?	no
BC Break report?	no
RFC?	no
Symfony version	3.3.10

Our project was running v3.2.6 and since it isn't supported anymore we wanted to switch to Symfony 3.3. We created a new branch based on our master branch and made some changes to the code (removing deprecated stuff, etc.) but no major changes.

When running the tests of our project in the new branch it takes 15 minutes and 26 seconds whereas it only takes 6 minutes and 30 seconds in the master branch.

I found this issue: doctrine/annotations#135 (comment) and we updated our dependency to doctrine/annotations from 1.4.0 to 1.5.0.

This already worked, it made our tests 5 minutes faster, so now it only takes 10 minutes and 50 seconds.

Type	Duration
master	6 minutes 30 seconds
update-branch	15 minutes 26 seconds
update-branch (updated annotations)	10 minutes 50 seconds

For all those tests I deleted the cache folders beforehand, did a composer install, etc. so I always have the same preconditions.

In the linked PR from doctrine/annotations @Ocramius said

as for the performance issue caused by multiple reset() or registerLoader() calls, that cannot be fixed without introducing BC breaks :(

so is there nothing else that can be done to improve performance?

What we changed

• replaced kernel.root_dir with kernel.project_dir (same for the methods getRootDir() in AppKernel)
• removed trusted_proxies from config.yml and now calling it in the app.php and app_dev.php

But this alone shouldn't be responsible for an execution time that is 4 minutes longer, right?

[Ocramius]

FWIW, the annotation loader should just disappear, assuming that class_exists() is a sufficient loader, but that can't be done in annotations 1.x

[kobelobster]

@Ocramius - Do you think that the things you pointed out are the reason for the long durations and that they would be fixed in a v2 version, so that we "ignore" this issue until then?

[stof]

@Ocramius see my comment in doctrine/annotations#145 (comment)
I think we can apply a BC optimization to the AnnotationRegistry for the case of multiple registration, which would be able to cover this case.

[dmaicher]

Maybe try https://github.com/dmaicher/doctrine-test-bundle. You can just use the "static cache" feature without the transactional connections.

This reduces the time for my phpunit testsuite by factor 4-5. Also the memory consumption is less than half.

[kobelobster]

I can try stuff out tomorrow since I'm not at work anymore.

[Ocramius]

Do you think that the things you pointed out are the reason for the long durations and that they would be fixed in a v2 version, so that we "ignore" this issue until then?

No, I don't know for sure - it needs to be profiled.

[kobelobster]

@dmaicher - I installed the bundle and used this config:

dama_doctrine_test:
  enable_static_connection: false

This speeds up the tests by 1 minute, they now need 9 minutes and 52 seconds.

[dmaicher]

@tzfrs ok interesting. For me the difference was more significant.

I don't quite understand the difference between symfony 3.2 and 3.3 for you though. I also recently upgraded my app from 2.8 to 3.3 and for me the test suite performance actually improved slightly and did not become worse 😕

So why is it slower for you only on 3.3?

[kobelobster]

That's what we're trying to figure out. There is already sth. I noticed. We currently have multiple bundles and when I run the tests in each bundle on it's own it doesn't matter if I'm on the 3.3 or 3.2 branch. The timings are always the same and together sum up to about ~ 6 minutes. But when I test the whole src folder I have the differences when using 3.2 vs 3.3.

This is our phpunit config

<?xml version="1.0" encoding="UTF-8"?>

<!-- http://phpunit.de/manual/4.1/en/appendixes.configuration.html -->
<phpunit xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:noNamespaceSchemaLocation="http://schema.phpunit.de/4.1/phpunit.xsd"
         backupGlobals="false"
         colors="true"
         bootstrap="app/tests.bootstrap.php">

    <testsuites>
        <testsuite name="Project Test Suite">
            <directory>src/*/*Bundle/Tests</directory>
            <directory>src/*/Bundle/*Bundle/Tests</directory>
            <directory>src/*Bundle/Tests</directory>
        </testsuite>
    </testsuites>

    <php>
        <ini name="error_reporting" value="-1" />
        <server name="KERNEL_DIR" value="app/" />
        <env name="BOOTSTRAP_CLEAR_CACHE_ENV" value="test"/>
    </php>

    <filter>
        <whitelist>
            <directory>src</directory>
            <exclude>
                <directory>src/*Bundle/Resources</directory>
                <directory>src/*Bundle/Tests</directory>
                <directory>src/*/*Bundle/Resources</directory>
                <directory>src/*/*Bundle/Tests</directory>
                <directory>src/*/Bundle/*Bundle/Resources</directory>
                <directory>src/*/Bundle/*Bundle/Tests</directory>
            </exclude>
        </whitelist>
    </filter>

    <listeners>
        <listener class="\DAMA\DoctrineTestBundle\PHPUnit\PHPUnitListener"/>
    </listeners>
</phpunit>

Do you know if it's possible to list the duration per folder in PhpUnit after the tests are completed? That way I could check which folders take way longer.

[NicoHaase]

You could either try johnkary/phpunit-speedtrap to see which tests run slow, or use a profiler like XHProf or Blackfire

[sroze]

For the records, I've experienced the same slowness when upgrading to Symfony 3.3 on a large application.

[kobelobster]

@NicoHaase, thanks, I already wrote a custom ResultPrinter. We have some namespaces where tests are now like 1 or 2 minutes longer. I will investigate. These tests are integration/elastic search tests.

Blackfire is also an option, we already have that integrated. If I don't find anything with the current approach I'll try Blackfire.

[kobelobster]

Ok, I did some assertions and there are like 80 tests which take 1-2 seconds longer, some tests which take 5 seconds longer, some tests which take 10 seconds longer, so it seems like every test got slower. What would really help is to create a cachegrind file for only one method while testing all methods. Is it somehow possible? I only found ways to always profile EVERYTHING.

[NicoHaase]

If you just run a single test, you are able to profile that execution. But be sure to run the test with a warmed up cache

[kobelobster]

Yes, but the problem is that running tests alone or just on a per bundle basis doesn't yield a different duration for the tests. The tests are only slower when I execute them all at once.

[NicoHaase]

Using XHProf, you could start running the profiler in the setup and write out the profile in the teardown of each test

[Ocramius]

Just profile everything over two runs and compare? It will be a massive cachegrind file, but it is ok-ish. Marco Pivetta http://twitter.com/Ocramius http://ocramius.github.com/

…

On Wed, Oct 18, 2017 at 12:04 PM, Theo Tzaferis ***@***.***> wrote: Ok, I did some assertions and there are like 80 tests which take 1-2 seconds longer, some tests which take 5 seconds longer, some tests which take 10 seconds longer, so it seems like every test got slower. What would really help is to create a cachegrind file for only one method while testing all methods. Is it somehow possible? I only found ways to always profile EVERYTHING. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#24596 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAJakH_OGaFDf6gBu3xxmwced2R-3uJ4ks5stc0dgaJpZM4P8Xe3> .

[michalv8]

@tzfrs Do you use Symfony WebTestCase (or other classes extending KernelTestCase and booting Symfony kernel)? In my company when we were migrating to 3.3 a couple of tests were using it and after Symfony update theirs run time increased on average from 50-200 ms to 2-4 seconds. Our best guess was the deprecation of ClassLoader component (booted kernel loads lots of classes so after switching only for composer cache it could slow down the execution in dev environment with no autoloading optimizations) but we didn't dig in deeper because these tests were already invalid and we got rid of extending of KernelTestCase (and timings came back to normal).

[theofidry]

A lot of my tests are way slower due to about 8000 deprecated calls made which are getting services from the container in the tests. I understand this is now deprecated as those services may be inlined so they should be made public, but you don't care if it's only for testing purposes. Is there a way to disable those deprecations [regarding private services] in tests?

[nicolas-grekas]

@theofidry making those services public for the test env, that's the only way to do it.
see discussion on #24543

[dmaicher]

Just to be sure: you have disabled the profiler in your tests?

profiler:
    enabled: false
    collect: false

Interesting that in my test suite (which is huge and has tons of services retrieved directly from the container) I don't see any performance drop at all due to deprecations.

[dmaicher]

Something to note: I usually run my tests with kernel.debug = false as its quite a bit faster:

3.3.10, kernel.debug = true:

=> Time: 9.88 minutes, Memory: 2848.01MB

3.3.10, kernel.debug = false:

=> Time: 4.31 minutes, Memory: 1548.01MB

I cannot easily benchmark using 3.2 currently. But maybe the difference between debug and no-debug is bigger on 3.3 now?

[dmaicher]

@tzfrs did you have any luck finding out more?

[nicolas-grekas]

A Blackfire profile would immediately stop the guess work that's happening here, please provide one...

[kobelobster]

Sorry! Totally forgot about that. @nicolas-grekas You're talking about a Blackfire profile for ALL tests?

[nicolas-grekas]

Or a subset of them that could hint the slowness yes.

[kobelobster]

Would need to profile everything, because only doing a subset yields the same results. It's only slower when running ALL tests. I'll report back.

[Ocramius]

Ah yes, some performance optimisations were indeed introduced. Still, can you try the replacement suggested in doctrine/annotations#162?

[kobelobster]

@Ocramius Which replacement are we talking about? Or do you want me to simply do a composer require on the commit of that PR?

[Ocramius]

@tzfrs find occurrences of ::registerLoader(), replace them with ::registerUniqueLoader()

[iamluc]

@tzfrs you can try to run some of the tests with the blackfire CLI (https://blackfire.io/docs/cookbooks/profiling-cli)

i.e.

blackfire run ./bin/phpunit MyTest.php

With this, no need to modify the tests

[kobelobster]

@Ocramius I replaced registerLoader with registerUniqueLoader for all occurrences (except the method registerUnloader itself of course).

Result: Time: 12.26 minutes, Memory: 2680.27MB

So it got faster again! Thank you. However, as you said, this would mean patching Symfony manually.

@iamluc Ah, I see! I'll try this and will report back. (Could however be, that I will report tomorrow, not today)

[kobelobster]

I just did a Blackfire profile. Here is a screen of the results where we have a big drop

The fact that gc has 71% could be alarming, right?

[nicolas-grekas]

Wow
Could you try using Symfony phpunit bridge instead of phpunit directly?

[kobelobster]

Sure, I am running it now with blackfire. Will update with results.

Update: Sorry! I don't think I will make this in time, because of an appointment. But this will be the first thing I do tomorrow and I'll update you again. Thanks for your help guys.

[kobelobster]

Good morning guys.

I just ran the command again SYMFONY_DEPRECATIONS_HELPER=disabled blackfire run vendor/symfony/symfony/src/Symfony/Bridge/PhpUnit/bin/simple-phpunit -c . but it seems like this leads to too much memory used because I'm getting this error

fatal error: runtime: out of memory

Sadly, it seems like I can't profile my tests with blackfire/phpunit-bridge

[nicolas-grekas]

My diagnosis is that for some reason, your tests create many objects internally, and the PHP garbage collector is struggling with them (that's the hint provided by Blackfire)
Then, enabling the bridge collects deprecations. And memory explodes.
You may try disabling the gc - and maybe calling it in some key "tearDownAfterClass".
You may also try fixing the deprecations.
And we may improve the bridge so it doesn't explode memory (but culprit needs to be confirmed before).

[kobelobster]

Yeah, we thought about that too. Especially since we have some legacy code where we access the container in UnitTests instead of mocking them (This is only a small part, however) and because our objects could have huge references (in the integration tests).

So SYMFONY_DEPRECATIONS_HELPER=disabled only disables the output, but collecting happens anyway? I mean, I could do a search/replace in the vendor/ folder and remove every deprecation trigger warning, but that would take some time.

But yes, I think fixing deprecations should be quickest/best solution. If the tests are getting slower with each Symfony release I'm 99% sure that this is because of the depracations. At least this is the most logical explanation.

I called gc_disable() in our tests.bootstrap.php, so for all tests, but as you can imagine, this also made my memory explode.

Putting it into every test at the right point would be much thinking, because that way we could also call the collect_cycles too often. So, I think we should fix our deprecations (or disable them completely).

I just added

error_reporting(0);
@ini_set('display_errors', 0);

to the tests.bootstrap.php. Let's see if this helps at all, next step would then be fixing the warnings.

Update: Setting error_reporting to 0 and display_errors to 0 as well yielded no change in time. So can it really be the deprecations?

[nicolas-grekas]

Can you try something else?
In the debug component, file ErrorHandler.php, there is a line like this one:

        if (100 < ++self::$silencedErrorCount) {

if you change that 100 to a 10000, does it change anything?

[kobelobster]

@nicolas-grekas

I did the tests (without the replacement of registerLoader to registerUniqueLoader)

Result with 100: Time: 14.5 minutes
Result with 10000: Time: 15.68 minutes

So it doesn't seem like it changed anything.

[francoispluchino]

I do not know if there is a connection with this issue, but maybe the doctrine/DoctrineBundle#763 issue can give an extra track, because I noticed an increase execution time of my functional tests caused by the double compilation of the cache for the container.

[ThomasLabstep]

Any update on this matter ?

We upgraded from Symfony 2.8 to 3.4.7 and our PHPUnit functional test suite went from 10 min to 50 min.

doctrine/annotations: v1.6.0

We will now try to use a profiler to see what's going on.

[mertoksuz]

@ThomasLabstep

If you did, could you share results please.

[ostrolucky]

This seems similar to #27053, only in my case tests blow up, but that can be nature of our tests, since we try to reuse variables there a lot.

Are your containers being regenerated during the run? Meaning, is var/cache/test/Container* being changed?

[rvanlaak]

TLDR; Symfony introduced the Client back/forward in history function in 3.3 via #22341 that internally keeps track of redirects. It can lead to huge delays or infinite loops on tests that use BrowserKit Client because by default redirects are followed. Disabling and limiting redirects on client for test environments will show tests that should be fixed.

Identify the problem

After trying to isolate this test speed degradation, we came to the conclusion that only the WebTestCase tests using Client were affected. All tests in our unit suite are just running fine. In other words, our functional and smoke tests were showing the degraded performance.

After more debugging it turned out that our smoke test were solely checking whether certain GET-requests were asserted using self::assertTrue($response->isSuccessful()). When the redirects are followed, the redirect most of the time is successful where this shouldn't have been. The test then is passing though.

Solution

After applying the following snippet, we were able to fix all tests and upgrade Symfony. The test suite even became a bit faster, because the redirects that did happen before are not in the test run anymore.

# Symfony\Bundle\FrameworkBundle\Client
$client->setMaxRedirects(1);
$client->followRedirects(false);

Hope this helps others to continue identifying where their tests fail.

Proposed fix

I'd propose to not use -1 as default value on Symfony\Component\BrowserKit\Client::$maxRedirects, as that can cause infinite loops. Would be great if we could formulate a PR for changing that. In my opinion, for test environments redirects should not be followed by default.

[stof]

@rvanlaak the PR you linked does not introduces following redirects at all (this exists since ages). It only adds the fact that redirects are skipped for back and forward. So if you don't use back or forward, there is nothing changing regarding infinite loops (and back and forward cannot make infinite loop as the history is finite)

[rvanlaak]

Will put some more time in a scenario to reproduce this asap. For now we're happy that we can roll out the 3.4 update because of the above change, and we wanted to share it as it might be the solution for others as well.

Maybe referring to that PR was premature, but it did seem the most viable commit when I was looking at the commits that happened to Client: https://github.com/symfony/symfony/commits/3.3/src/Symfony/Component/BrowserKit/Client.php

[stof]

@rvanlaak but is the issue related to tests using the client, or to tests booting a kernel (or to something else) ? the usage of the client might not be the only difference between these tests.

[ThomasTr]

My tests went after Upgrade from symfony 4.0.11 to 4.1.0 from

  [phpunit] Time: 1.36 hours, Memory: 200.70MB
  [phpunit] 
  [phpunit] OK (563 tests, 1189 assertions)

to

  [phpunit] Time: 8.36 hours, Memory: 754.50MB
  [phpunit] 
  [phpunit] OK (563 tests, 1189 assertions)

Around 350 unit tests, rest functional tests with code coverage tested.
Still looking around and try to profile...

[KowolTSH]

Same issue for the functional tests
Symfony 4.0.8:

Memory: 220.00MB
OK (2618 tests, 4470 assertions)

Symfony 4.1.0

Memory: 490.00MB
OK (2618 tests, 4470 assertions)

[nicolas-grekas]

Without a profile, there is nothing to do here. I'm therefore closing. Don't hesitate to create new issues with actual information that could hint what is slow, e.g. with https://blackfire.io