Skip to content

Performance regression in DEV mode since "Use VarDumper in the profiler" #23233

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
raziel057 opened this issue Jun 20, 2017 · 36 comments
Closed
Labels
Milestone

Comments

@raziel057
Copy link
Contributor

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

I know that VarDumper in the profiler brings lot of improvements especially when displaying objects but it's a bit weird to loose so much performance on some pages when upgrading to Symfony 3.3.

In fact the more important impact is linked to pages that are composed with render controller. Exceution time and memory usage increases a lot. Please check the benchmark file in attachment.

Benchmark-20170620.pdf

To resume (each widget is integrated to a dashboard as render controller):
In PHP 5.6.30:

  • Dashboard with 12 widgets: SF 3.1.5: 978ms - SF 3.3.2: 2499ms -> +255%
  • Dashboard Global with 14 widgets: SF 3.1.5: 1430ms - SF 3.3.2: 3307ms -> +231%

In PHP 5.6.30:

  • Dashboard with 12 widgets: SF 3.1.5: 406ms - SF 3.3.2: 861ms -> +212%
  • Dashboard Global with 14 widgets: SF 3.1.5: 748ms - SF 3.3.2: 1338ms -> +179%

I know some work have been done to improve the performance here: #19986

I'm not sure if something can be done, especially for render controller use case, because the profiling is done for all sub requests even if a lot of data comes from the Master Request (Doctrine, Security, Twig, etc). I just don't understand why the memory usage increase as much. Please also note that the Dashboard page doesn't contains any form. It seems the Routing page of sub requests make the memory increase a lot.

I let you close the ticket if you think that nothing can be done.

@javiereguiluz
Copy link
Member

I noticed a similar slowdown. See the profile of the same page of a complex Symfony app using 3.2 and 3.3 versions:

3.2.9

before-profiler

3.3.2

after-profiler

Main differences

comparison-profiler

@fabpot
Copy link
Member

fabpot commented Jun 20, 2017

/cc @nicolas-grekas

@nicolas-grekas
Copy link
Member

This means too much data is being cloned. Can you think of any object that could be collected but should be skipped because it's not displayed? There should be some to explain the difference.

@graemechapman
Copy link

I am also seeing a massive difference in memory usage. My php memory limit was previously set to 64mb, since upgrading from 3.2.9 to 3.3.2 I've had to increase this to 160mb to avoid getting out of memory errors. I have tested on a few different Symfony versions, and this change occurs between 3.3.0 and 3.3.1.

I also noticed that the performance tab shows about 50% increased peak memory usage, all consumed by the ProfilerListener.

With a lower memory limit, an out of memory exception always occurs at https://github.com/symfony/symfony/blob/3.3/src/Symfony/Component/HttpKernel/DataCollector/DataCollector.php#L44

The memory usage in production environment is unaffected.

I am currently running PHP 5.5.38.

@xabbuh xabbuh added this to the 3.3 milestone Jun 20, 2017
@raziel057
Copy link
Contributor Author

Performance Page - Master request

master_request

If I check the Performance page of a Sub Request (widgetGenderAction), I can see that Total execution time doesn't correspond to the processing of the sub request (11ms). Is it normal? It does not match either the total execution time of Master Request (825ms or the total of Sub Request time 179 ms).

sub_request_perf

If I click on the Routing page of Sub Request, I got an OutOfMemory exception (on php 7.1.6 with memory_limit=128mb)

routing_error

When I increase the memory limit, I got:

routing_sub_request

None route match for Sub Requests so maybe the Routing data collecting could be avoid here?

@stof
Copy link
Member

stof commented Jun 21, 2017

Well, the timing of a request does not include the time spent in ProfilerListener (this is a chicken and egg issue: how do you measure the time until after you are done saving the result of the measure ?).

And the issue here seems to be that the Symfony initialization time is add in subrequests too, while it is actually paid by the master request only (you pay it once per process only).
The collector would need to skip collecting this part of the timing when collecting info for a subrequest.

@stof
Copy link
Member

stof commented Jun 21, 2017

And this matches numbers: 293ms is 282ms (SF initialization, copied from the master request by mistake) + 11ms (time collected for the subrequest)

@raziel057
Copy link
Contributor Author

@stof Ok understood but in that case the figure in master request is not accurate (5ms). Check my screenshot of Master Request.

What is your opinion about the routing part?

@javiereguiluz
Copy link
Member

Not sure if related to this, but the files generated by the profiler (var/cache/dev/profiler/*) are HUGE. It takes more than 2 MB per request in some of my applications. Other users have complained about this too.

@markitosgv
Copy link
Contributor

markitosgv commented Jun 26, 2017

Hi!

We have same issue, when upgrading to Symfony 3.3.x.

For example I've got a page with a form field EntityType, which loads about 500 entities to render a select dropdown, now profiler generates a >50Mb file and 404 debug toolbar error appears.

If I downgrade to Symfony 3.2.x, same page, generates a 1.8Mb profiler file.

@XWB
Copy link
Contributor

XWB commented Jun 27, 2017

Profiler is pretty slow after upgrading to Symfony 3.3. Furthermore, storage space is gigantic. At some pointed it reached over 100 GB. The only thing we can do is removing /cache/dev/profiler/ at the end of the day. This behavior makes the profiler unworkable for now.

image

@javiereguiluz
Copy link
Member

I don't know if this is a bug or a feature that must be reverted, but I've added the "Critical" label because fixing this should be our top priority. Thanks!

@nicolas-grekas
Copy link
Member

Please post one of these big files.

@XWB
Copy link
Contributor

XWB commented Jun 28, 2017

Profiler directory reached 110 GB today:

image

@mvrhov
Copy link

mvrhov commented Jun 28, 2017

@XWB: You are pressing F5 too much :P

@XWB
Copy link
Contributor

XWB commented Jun 28, 2017

Well it never was an issue prior to Symfony 3.3 ;)

@XWB
Copy link
Contributor

XWB commented Jun 29, 2017

@nicolas-grekas What file would you like to see? Each directory within /cache/dev/profiler/ contains a lot of subdirectories, each being 454 MB in size:

image

@markitosgv
Copy link
Contributor

Please, any update? I can't upgrade to Symfony 3.3 :(

@theofidry
Copy link
Contributor

@markitosgv it's not progressing much because we don't have any reproducible code. If you can publish such of those files or publish a repo where this error occurs I'm sure it would be solved in no time :)

@szymach
Copy link

szymach commented Jul 4, 2017

Maybe it is linked to the Symfony's web server? I know that sometimes you can get extremely slow performance out of it (like when rendering PDFs with KNPSnappyBundle). Also, this drop is new, since I was able to run a project on my PC on 3.3.0 without any issues when it was initially released.

@graemechapman
Copy link

Maybe it is linked to the Symfony's web server? I know that sometimes you can get extremely slow performance out of it (like when rendering PDFs with KNPSnappyBundle).

I'm seeing similar issues when using Apache.

@IwfY
Copy link

IwfY commented Jul 4, 2017

For us the problem is most noticeable on Sonata admin pages (3.20.1).
Using Twig 2.3 instead of 2.4 makes it better, it's still a noticeable performance drop.

Using Symfony 3.3.2, Apache.

@markitosgv
Copy link
Contributor

markitosgv commented Jul 4, 2017

We are using MongoDB, Nginx and PHP 7. You can try with an EntityType in a form (in our case DocumentType) with ~400 results for example to notice that.

@szymach
Copy link

szymach commented Jul 4, 2017

Oh yeah, I forgot to mention I do have a lot (~280) of depreciations messages out of Twig, since the libraries I use still use it in version 1.20-ish and I can not switch to 2.x. Could be another lead? PHP 7.1 btw.

@nicolas-grekas
Copy link
Member

Please share one of the big files generated by the profiler.

@szymach
Copy link

szymach commented Jul 4, 2017

@nicolas-grekas I have a ~400MB profiler file I could share, but I the question is where do I send it? Is there any sensitive data in those files I should be worried about, or can I just upload it to some file sharing service without worry?

@ctaverne
Copy link

ctaverne commented Jul 4, 2017

Hi, Same issue here. Memory usage is increasing massively.
We can't upgrade to 3.3

@nicolas-grekas
Copy link
Member

Hi all, could you please try #23413 and report any improvement?

fabpot added a commit that referenced this issue Jul 5, 2017
…s-grekas)

This PR was merged into the 3.3 branch.

Discussion
----------

[VarDumper] Reduce size of serialized Data objects

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

By using `Stub` objects a lot, especially for arrays, `Data` objects generate heavy serialized strings.
By implemeting `Serializable` on `Data`, this PR removes most of the boilerplate.

This PR also removes duplicate data in `LoggerDataCollector`, and reduces the backtrace of silenced errors to their 3 last items - which should be enough - and is otherwise responsible for a significant portion of the serialized payloads.

This is not the last possible step towards shrinking serialized profiles, but the next one is more complex -and maybe this one is good enough? Please give feedback if you can.

Commits
-------

70bd2bc [VarDumper] Reduce size of serialized Data objects
@fabpot fabpot closed this as completed Jul 5, 2017
@wadjeroudi
Copy link

@nicolas-grekas Thx, it seems better, but I feel like it's still slower than 3.3.2. Will wait for others to post benchmarks.

@nicolas-grekas
Copy link
Member

See #23415, Backfire profiles welcomed.

@markitosgv
Copy link
Contributor

Hi guys, for me problem with Symfony 3.3.4 still persists.

image

Same page, with symfony 3.2.9 works :/

@nicolas-grekas
Copy link
Member

nicolas-grekas commented Jul 6, 2017

In fact, this maybe related to a high number of deprecations, not only to the way the data is collected in 3.3. Is that plausible? Can you post a screenshot of the profiler deprecation panel?

@markitosgv
Copy link
Contributor

markitosgv commented Jul 6, 2017

This is another page deprecations info:

image

But, I think it's not about deprecations, look:

...
->add(
    'activeOrganization',
    DocumentType::class,
    [
        'label'       => 'Active Organization',
        'class'       => Organization::class,
        'attr' => [
            'placeholder' => 'userContact.activeOrganization.placeholder',
        ],
        'query_builder' => function ($qb) {
            return $qb->createQueryBuilder()->select('contact.name')->select('owner')->field('owner')->prime(true);
        },
    ]
)
...

If I put a limit in the query, like 100, It works ok. I know this is not the best way to show a select with a huge collection of entities, but it's ok for this purpose.

@szymach
Copy link

szymach commented Jul 6, 2017

I have this issues on a page where there's a query returning a single record, so I do not think it is related to a lot amount of data being fetched from the database.

@nicolas-grekas
Copy link
Member

Please open specific issue, related to the Form panel it looks like?

@XWB
Copy link
Contributor

XWB commented Jul 6, 2017

In fact, this maybe related to a high number of deprecations, not only to the way the data is collected in 3.3. Is that plausible? Can you post a screenshot of the profiler deprecation panel?

I have only 1 deprecation notice in my application.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests