Big memory usage increase since Symfony 3.2

[ostrolucky]

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

After upgrade from Symfony 3.1 to Symfony 3.2, memory usage of our phpunit tests increased from ~170MB to 3GB!

I tracked this down to this PR #19656

When we set option php_errors['log'] to false, it decreased to normal level.

We are using lot of functional tests via Symfony\Bundle\FrameworkBundle\Test::createClient

[dxops]

$options parameter for \Symfony\Bundle\FrameworkBundle\Test\WebTestCase::createClient should contain ['debug' => false] value

[peterrehm]

@gadelat Does this fix your issue?

[ostrolucky]

No it doesn't. And even if it did, it's not a proper fix.

• I shouldn't be required to change my application code to avoid sudden memory leak in minor version upgrade, that's a regression. Setting configuration of php_errors['log'] to false in my config_test.yml is much easier.
• I don't want to disable debug mode. Normally it doesn't have such huge performance impact. Disabling it makes test debugging harder

[nicolas-grekas]

just out of curiosity, does the memory usage increase or decrease when replacing https://github.com/symfony/symfony/blob/master/src/Symfony/Component/Debug/ErrorHandler.php#L418-L436 by only $backtrace = $backtrace ?: $errorAsException->getTrace(); (keeping L419 really?)

[ostrolucky]

Not really @nicolas-grekas - It doesn't seem to have noticable effect.

[Jean85]

Have you tried the latest patch, 3.2.4?

[nicolas-grekas]

Could also be fixed by #21061?

[ostrolucky]

No, it even got worse for php_errors['log'] = false after update

Symfony 3.2.3: 107.02MB. Symfony 3.2.4: 221.96MB

#21061 Doesn't help either

[ostrolucky]

So, I found something interesting today. This bug does NOT occur when symfony/phpunit-bridge is installed

EDIT: This is what's causing to stop memory leak:

symfony/src/Symfony/Bridge/PhpUnit/bootstrap.php

Line 28 in e58be70

DeprecationErrorHandler::register(getenv('SYMFONY_DEPRECATIONS_HELPER'));

[nicolas-grekas]

Should be fixed by #21973

[ostrolucky]

Unfortunately the linked patch does not have any effect.

[theofidry]

@gadelat sorry for my naive POV:

• You said you trace it back to [FrameworkBundle][Debug] Fix default config and cleaning of traces #19656, but 1. are you certain of this? and 2. which change exactly in there?
• Is there a way to get a reproducible environment? I mean in all good faith, I don't think @nicolas-grekas is neglecting the issue or that there is many people experimenting this. It may not be trivial to re-produce and then much harder to trace back, so unless having the proper environment, it's very hard to actually find the fix for it.

[nicolas-grekas]

Please provide a Blackfire profile, could help a lot also.

[ostrolucky]

I found the problem...

Monolog strikes again! Dammit I tried to kill such source of problem in symfony/monolog-bundle#165 by proposing to disable DebugHandler in CLI. Now it strikes again under different name by introducing DebugProcessor in #20416, which is basically the same thing.

It's like a Hydra. You get rid of one of the monolog memory loggers, another shows up.

You can reproduce the problem by putting this in application code (e.g. in DefaultController of symfony/symfony-standard):

$this->get('event_dispatcher')->addListener($eventName = bin2hex(random_bytes(100000000)), function() {});
$this->get('event_dispatcher')->dispatch($eventName, new Event());

The problem I was having specifically in this ticket can be reproduced by removing symfony/phpunit-bridge, setting custom phpunit bootstrap (where you boot the symfony kernel - this sets the error handler to Symfony\Component\Debug\ErrorHandler first which then happily pushes those messages to that pesky DebugProcessor) and triggering this code:

@trigger_error(bin2hex(random_bytes(100000000)), E_USER_DEPRECATED);

Root issue needs to be fixed, which is that logs for web profiler are stored in memory even in CLI mode, where it's useless.

I've lost something like 40hours debugging this issue and more in past because of DebugHandler, guys please stop doing this to me.

[jakzal]

What if we cleared records if certain (configured) number of entries was hit?

[ostrolucky]

If you do that, you will make Debugprocessor unreliable. If you really want to avoid making this http only (I still don't see a reason for having it in CLI at all, but whatever), better would be to flush the records into file after a certain value.

[nicolas-grekas]

Fixed by #23465 on branch 3.3

[ostrolucky]

@nicolas-grekas It doesn't fix this issue (we always use framework[profiler][collect]=false configuration in config_test.yml), reopen please.

Fresh round of tests:

Symfony version:	3.4.x-dev (b24a338)	3.2.11	3.1.10
Memory (php_errors['log'] = null)	3140.00MB	2520.00MB	108.00MB
Memory (php_errors['log'] = false)	130.00MB	112.00MB	-
Time (php_errors['log'] = null)	12.82minutes	10.44 minutes	3.61 minutes
Time (php_errors['log'] = false)	3.83 minutes	3.7 minutes	-

Additionaly, apparently it affects speed too. I assume I didn't notice that before because it was masked by annotations slowdown issue which had similar speed impact factor.

After these tests I've generated blackfire profile and will share it upon request privately only.

[nicolas-grekas]

Profile welcomed

[ostrolucky]

@nicolas-grekas I've sent it to you via slack on symfony channel.

But props to you if it will help you. In my opinion it shows pretty useless data for this issue, that's why I didn't provide it sooner.

[ostrolucky]

After plenty more testing, profiling and experiments I no longer think this is a bug of Symfony, but rather some weird GC issue, maybe in combination with some hardware, as I can't reproduce this on PC in work in identical sandbox environment. Therefore closing