Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

Appearance settings

[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

Closed
wants to merge 1 commit into from

Conversation

vtsykun
Copy link
Contributor

@vtsykun vtsykun commented Jul 22, 2017

Q A
Branch? 3.4
Bug fix? yes
New feature? no
BC breaks? no
Deprecations? no
Tests pass? -
Fixed tickets -
License MIT
Doc PR -

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/graph

After apply my fix I get more 80% performance
selection_061

Thanks,
Vladimir

@linaori
Copy link
Contributor

linaori commented Jul 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
Copy link
Member

nicolas-grekas commented Jul 23, 2017

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.
Yet, as I understand the issue, all sub-requests have the same logs, and we still serialize them several times?
Also, which exact Symfony version was the profile done with? Can you try v3.3.5 if that was an earlier version?

@vtsykun
Copy link
Contributor Author

vtsykun commented Jul 23, 2017

I profile v3.3.5 and get same result https://blackfire.io/profiles/76d6907f-ef47-4c5f-9fea-9a73c926e2f1/graph.
Yes, all sub-requests have the same logs, and we still serialize them several times.
It problems also exist on v2.8.* Our application used 2.8.13. We noticed that debug toolbar not showing (error not found 404) on some heavy pages. The reason was that serialize and collects logs for each sub-request take a lot of time. Then we could not find a more correct solution than this https://github.com/orocrm/platform/blob/master/src/Oro/Bundle/LoggerBundle/DataCollector/LoggerDataCollector.php

@nicolas-grekas
Copy link
Member

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
Copy link
Contributor

linaori commented Jul 23, 2017

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
Copy link
Member

Wondering: what would be the downside of setting framework.profiler.only_master_requests to true?

@vtsykun
Copy link
Contributor Author

vtsykun commented Jul 23, 2017

Of course it work framework.profiler.only_master_requests: true because hides cause of the problems.
After disable gc: https://blackfire.io/profiles/e0dc05e2-8769-4a29-a220-5228599e9c47/graph
I think we should not show the same list of logs for each sub-request and master request. For example if I open debug toolbar for doctrine query I will see different count of sql query for each sub-request, but not for logs toolbar.
I will try to implement this, It also should be fix performance because the same log will not be processed many times for each sub-request

@nicolas-grekas
Copy link
Member

nicolas-grekas commented Jul 24, 2017

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
Copy link
Contributor Author

vtsykun commented Jul 24, 2017

It is improve performance by execute time, but not memory
Comparison result https://blackfire.io/profiles/compare/94da04c4-56a4-48f0-93fe-9a8b25fc28d0/graph

Thanks,
Vladimir

@nicolas-grekas
Copy link
Member

New profile welcomed, I pushed a new patch on #23644 :)

@vtsykun
Copy link
Contributor Author

vtsykun commented Jul 24, 2017

It has improved performance for VarDumper https://blackfire.io/profiles/30521d32-392e-435a-8f01-af4492df0f55/graph
Thank you!

@vtsykun vtsykun closed this Jul 24, 2017
@nicolas-grekas
Copy link
Member

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 vtsykun deleted the patch-logger-collector branch July 26, 2017 08:51
@vtsykun
Copy link
Contributor Author

vtsykun commented Jul 26, 2017

fabpot added a commit that referenced this pull request Jul 28, 2017
…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
nicolas-grekas added a commit that referenced this pull request Apr 20, 2018
…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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants
Morty Proxy This is a proxified and sanitized view of the page, visit original site.