-
-
Notifications
You must be signed in to change notification settings - Fork 9.6k
[HttpKernel] Garbage collection in LoggerDataCollector took about 50% of all execution time #23620
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
Is this also the case on 3.2+? Because here I saw massive performance issues in dev mode, but have been unable to trace the cause. |
This patch cannot be merged as is because it forces one single list of logs, thus defeats the purpose of using objects for scope isolation. |
I profile v3.3.5 and get same result https://blackfire.io/profiles/76d6907f-ef47-4c5f-9fea-9a73c926e2f1/graph. |
What's the effect of this patch? --- a/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php
+++ b/src/Symfony/Component/HttpKernel/EventListener/ProfilerListener.php
@@ -105,6 +105,10 @@ class ProfilerListener implements EventSubscriberInterface
public function onKernelTerminate(PostResponseEvent $event)
{
+ if ($gc = gc_enabled()) {
+ gc_disable();
+ }
+ try {
// attach children to parents
foreach ($this->profiles as $request) {
// isset call should be removed when requestStack is required
@@ -122,6 +126,11 @@ class ProfilerListener implements EventSubscriberInterface
$this->profiles = new \SplObjectStorage();
$this->parents = new \SplObjectStorage();
+ } finally {
+ if ($gc) {
+ gc_enable();
+ }
+ }
}
|
We've been experiencing similar issues on certain pages in 3.2, though it doesn't necessarily happen every request on that page, it simply gives an error opening the profile "randomly". |
Wondering: what would be the downside of setting |
Of course it work |
This won't fix the issue of having the logs serialized several times, yet it'd be really nice if you could revert that patch above (adding gc_disable), and try #23644 instead. What's the resulting profile? |
It is improve performance by execute time, but not memory Thanks, |
New profile welcomed, I pushed a new patch on #23644 :) |
It has improved performance for VarDumper https://blackfire.io/profiles/30521d32-392e-435a-8f01-af4492df0f55/graph |
I don't understand the memory increase. Can you please do a last profile with the new patch on the PR see if it improves things? |
The memory increase is still observed again after merge #23644 |
…grekas) This PR was merged into the 3.3 branch. Discussion ---------- [VarDumper] Keep and reuse array stubs in memory | Q | A | ------------- | --- | Branch? | 3.3 | Bug fix? | yes | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | yes | Fixed tickets | - | License | MIT | Doc PR | - (to be reviewed [ignoring whitespaces](https://github.com/symfony/symfony/pull/23683/files?w=1)) As highlighted by @vtsykun in #23620, the patch in #23644 improves performance but increases the memory usage. The issue is that even a small `array($k => $v)` consumes more memory than a `new Stub()`. That's a shame, but since our small arrays have a low variety, we can keep them in a cache and leverage php's COW mechanism to reduce memory. Effectively, this creates a memory leak. But the leak is upper bounded by the data you had already in memory, since that's what is cloned. Looking at the numbers, it looks worth it: | | 3.3.5 | +#23644 | +this PR | --- | --- | --- | --- | Wall Time | 39.4s | 26.1s | ~~18.6s~~ 17.3s | Memory | 391MB | 539MB | ~~217MB~~ 216MB https://blackfire.io/profiles/compare/846b58bc-7863-4502-9ca2-f82eebd4173f/graph Commits ------- 92fa55d [VarDumper] Keep and reuse array stubs in memory
…fferent sub-requests (vtsykun) This PR was merged into the 4.1-dev branch. Discussion ---------- [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests | Q | A | ------------- | --- | Branch? | 4.1 | Bug fix? | yes | New feature? | no | BC breaks? | no | Deprecations? | no | Tests pass? | - | Fixed tickets | #23620 | License | MIT | Doc PR | - This PR fixed performance problem in dev mode and prevent logs serialize several times for each sub-request. STR: 1) Install any symfony application v2.8-3.4 2) Create a simple page with 20-50 sub-requests and 5k-10k logs 3) Open page in dev mode **Actual** - debug toolbar not open (404 not found) - sets of logs (in the logger debug panel) for different requests are same - log processing takes about 20-30s - gc also run about 50% of execution time **Expected** - Debug toolbar should be open - As developer, I want to see in logger panel only those logs that are relevant to the given sub-request ### Profile and performance Tested on page with 7k logs and 70 sub-request. Comparison: - v3.3.5 - this patch: https://blackfire.io/profiles/compare/b1d410b3-c4a7-4778-9b6d-514f72193e28/graph - v3.3.5 - patch #23644 https://blackfire.io/profiles/compare/d0715b04-7834-4981-8da2-9f1dcb2ef90c/graph Commits ------- d0cb1de [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests
When save the profiler, the method
LoggerDataCollector:lateCollect
called for each sub-request on the same sets of logs. For example I profile page with 70 sub-requests and 7k logs https://blackfire.io/profiles/bc726df2-ec8d-4f1b-bc1b-5b09a1f3f141/graphAfter apply my fix I get more 80% performance

Thanks,
Vladimir