Deprecations causing big performance hit in dev ProfilerListener #24625
Comments
|
You should look into what is doing "unserialize". I'm not sure it's legitimate to unserialize at all at this stage. Without a real (Blackfire) profile, you're on your own :) |
|
Hmm you were right about unserialize, this was the result of the second app_dev call, which is from the toolbar. I'm diving into the actual result now and seeing a different result. Sadly I'm still not able to install blackfire io, so I will have to do with webgrind to analyze it. If you want, I can supply the cachegrind files of the screenshots below privately. I believe this issue should be 100% reproducible by triggering a load of deprecations. Total pre-deprecation Total post-deprecation Function calls pre-deprecation Function calls pos
8000
t-deprecation Function Graph pre-deprecation Function Graph post-deprecation Callstack of the LoggerDataCollector |
|
How's the log panel like? Can you fully expand one deprecation listed there to see what's nested in the collected stack trace? |
|
I can provide you the exact data on Tuesday earliest. It's basically the deprecation message with some additional information and a context stored in it (line numbers etc). From what I can tell, all the data needed for exception messages. Each item in this array had 6~8, maybe more rows per array item, containing at least the context array with multiple rows. |
|
Same here. With just 63 deprecations, the profiler listener more than triples its execution time:
And here is the stack trace of one of those deprecations:
|
|
@nicolas-grekas, here's what's actually in there (quite a lot).
|
|
Please report behavior with #24895 |
|
I've noticed a significant improvement after testing #24895 changes. Thanks! |
… file+line (nicolas-grekas) This PR was merged into the 3.4 branch. Discussion ---------- [Debug] More aggressively aggregate silenced notices per file+line | Q | A | ------------- | --- | Branch? | 3.4 | Bug fix? | no | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | yes | Fixed tickets | #24625 | License | MIT | Doc PR | - By aggregating silenced notices (deprecations mostly) per file+line instead of just per message, we loose some accuracy, but gain performance. Commits ------- 9ab7559 [Debug] More aggressively aggregate silenced notices per file+line
|
@fabpot the provided patch did not fix anything for this issue, should probably remain open |
|
@iltar can you try this patch? --- a/src/Symfony/Component/Debug/ErrorHandler.php
+++ b/src/Symfony/Component/Debug/ErrorHandler.php
@@ -715,7 +715,7 @@ class ErrorHandler
}
if (!($throw || $this->scopedErrors & $type)) {
for ($i = 0; isset($lightTrace[$i]); ++$i) {
- unset($lightTrace[$i]['args']);
+ unset($lightTrace[$i]['args'], $lightTrace[$i]['object']);
}
} |
|
@iltar this one: --- a/src/Symfony/Component/HttpKernel/EventListener/DebugHandlersListener.php
+++ b/src/Symfony/Component/HttpKernel/EventListener/DebugHandlersListener.php
@@ -86,7 +86,7 @@ class DebugHandlersListener implements EventSubscriberInterface
$handler->screamAt($levels);
}
if ($this->scope) {
- $handler->scopeAt($this->levels);
+ $handler->scopeAt($this->levels & ~E_USER_DEPRECATED & ~E_DEPRECATED);
} else {
$handler->scopeAt(0, true);
} |
|
Applying just the second patch reduced it by 100~150ms, not optimal, but better. Old (for reference): New: |
|
OK, fixed in #24910 then. |
|
Yes, it's already a good improvement as it reduced the time in the profiler listener by 20~30%, so that's awesome, thanks! I hope that I can use blackfireio in the near future instead |
|
An additional yet important note: |
|
@iltar would love to ear how the param improves your setup |
…ecations (nicolas-grekas) This PR was merged into the 3.3 branch. Discussion ---------- [HttpKernel][Debug] Remove noise from stack frames of deprecations | Q | A | ------------- | --- | Branch? | 3.3 | Bug fix? | yes | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | yes | Fixed tickets | #24625 | License | MIT | Doc PR | - Collecting arguments of deprecations is too heavy, and was unintended in fact. Commits ------- f154be3 [HttpKernel][Debug] Remove noise from stack frames of deprecations
|
I'll give that one a shot on Monday, I've seen it come by and it looks really promising! |
|
@nicolas-grekas I can confirm that performance is increased by that setting. My local env (7.1, opcache, xdebug), the average request time is down by 100~300ms on the same page. The profiler listener is about 30~60ms faster. What I mainly noticed, is that the page loads are very similar: 850ms~950ms rather than 950~1250. Having a big project with a lot of files, this will certainly improve performance for at least dev. Sadly we're only running new relic on 1 production server, so I won't know the actual performance gain of 3.4 in prod with properly configured opcache. In my local environment I don't notice a real change with that setting, but I have no proper profiling available here. |
|
Forgot to add my cachegrind result (3.4.0-BETA4) with the parameter active:
|
|
For All looking for Out of memory exception after deploy - check permissions on var/cache and var/log directories |
When you trigger a lot of deprecations, they will be stored in the profiler. However, this causes a massive performance hit on all dev pages triggering those. from 5 to 89 deprecations, causes the profiler listener to go from roughly 300 to 900ms.
For 3.4, this deprecation is causing most issues:
symfony/src/Symfony/Component/DependencyInjection/Container.php
Line 277 in 1f92e45
Pre deprecation
Post deprecation
The cause seems to be the amount of unserialize function calls in the Stub.
Stub::unserialize()goes from4870to23570.Pre deprecation
Post deprecation
The text was updated successfully, but these errors were encountered: