Uh oh!
There was an error while loading.Please reload this page.
- Notifications
You must be signed in to change notification settings - Fork9.7k
[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 ourterms of service andprivacy statement. We’ll occasionally send you account related emails.
Already on GitHub?Sign in to your account
Uh oh!
There was an error while loading.Please reload this page.
Conversation
linaori commentedJul 22, 2017
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. |
nicolas-grekas commentedJul 23, 2017 • edited
Loading Uh oh!
There was an error while loading.Please reload this page.
edited
Uh oh!
There was an error while loading.Please reload this page.
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. |
vtsykun commentedJul 23, 2017
I profile v3.3.5 and get same resulthttps://blackfire.io/profiles/76d6907f-ef47-4c5f-9fea-9a73c926e2f1/graph. |
nicolas-grekas commentedJul 23, 2017
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();+ }+ } } |
linaori commentedJul 23, 2017 • edited
Loading Uh oh!
There was an error while loading.Please reload this page.
edited
Uh oh!
There was an error while loading.Please reload this page.
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". |
nicolas-grekas commentedJul 23, 2017
Wondering: what would be the downside of setting |
vtsykun commentedJul 23, 2017
Of course it work |
nicolas-grekas commentedJul 24, 2017 • edited
Loading Uh oh!
There was an error while loading.Please reload this page.
edited
Uh oh!
There was an error while loading.Please reload this page.
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? |
vtsykun commentedJul 24, 2017
It is improve performance by execute time, but not memory Thanks, |
nicolas-grekas commentedJul 24, 2017
New profile welcomed, I pushed a new patch on#23644 :) |
vtsykun commentedJul 24, 2017
It has improved performance for VarDumperhttps://blackfire.io/profiles/30521d32-392e-435a-8f01-af4492df0f55/graph |
nicolas-grekas commentedJul 25, 2017
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? |
vtsykun commentedJul 26, 2017
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~~ 216MBhttps://blackfire.io/profiles/compare/846b58bc-7863-4502-9ca2-f82eebd4173f/graphCommits-------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.42) Create a simple page with 20-50 sub-requests and 5k-10k logs3) 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 performanceTested 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#23644https://blackfire.io/profiles/compare/d0715b04-7834-4981-8da2-9f1dcb2ef90c/graphCommits-------d0cb1de [HttpKernel] LoggerDataCollector: splitting logs on different sub-requests
When save the profiler, the method
LoggerDataCollector:lateCollectcalled for each sub-request on the same sets of logs. For example I profile page with 70 sub-requests and 7k logshttps://blackfire.io/profiles/bc726df2-ec8d-4f1b-bc1b-5b09a1f3f141/graphAfter apply my fix I get more 80% performance

Thanks,
Vladimir