1.16.13 major performance issue caused by template locator -> max_execution_time error

[dfinfo]

Hi,

first i'd like to thank a lot Javier and all the contributors for the really good work with EasyAdminBundle. I use it in may daily work and it saves me so much time. Thanks a lot.

After composer update, it's impossible for me to get my current project working. Always got max execution time error during template location. After trying to revert my modifications, still here. Reading EasyAdminBundle releases notes, i found a bug fix "[803e84b] Improved how custom templates are looked for (@javiereguiluz)" that alert me.

I reverted EasyAdminBundle to version 1.16.12 and the problem is solved.

Is it a bug ? Are there other people experiencing this behavior ?

Any advice would be really appreciated.

Denis

[javiereguiluz]

Thanks for reporting this. I've used the EasyAdmin Demo application and compared 1.16.12 with 1.16.13, but I can't find any performance issue. See comparison: https://blackfire.io/profiles/compare/45ebabc9-e38f-470c-8b3d-ad9847e53a01/graph

Could you please profile the application to see which parts of this bundle are causing the performance penalty? Thanks!

[dfinfo]

Hi Javier,

thank you for your answer. Unfortunately i'm not comfortable with application profiling. I know i should but i don't use those tools and don't know how to do so, i have no one installed also.

I tried EasyAdmin Demo with both 1.16.12 and 1.16.13 and it works so the problem could be in my app, maybe the way i use custom templates.

In EasyAdmin Demo custom template is used only for a field in user list, in my app i use this (here is an example entity config) :

        ModalEtape:
            class: Dfinfo\Gcaue\ConseilCollectivitesBundle\Entity\Etape
            controller: Dfinfo\EasyAdminExtensionsBundle\Controller\ApiController
            templates:
              new:  '@DfinfoEasyAdminExtensionsBundle/easy_admin/modal.html.twig'
              edit: '@DfinfoEasyAdminExtensionsBundle/easy_admin/modal.html.twig'
            form:
              form_options:
                attr:
                  data-target: projet_etapes
              fields:
                - property: natureEtape
                  label: Etape.form.nature
                  type_options:
                    attr:
                      data-modal-select2: true
                    required: true
                - property: dateEtape
                  label: common.form.date
                  type_options:
                    widget: 'single_text'
                    attr:
                      date-format: dd/mm/yyyy
                      lang: fr
                      class: input-short
                - property: commentaire
                  type_options:
                    attr:
                      rows: 3
                - property: conseillers
                  repository:
                    function: createOrderByNomWhereTypeAnnuaireQueryBuilder
                    params: [personnel]
                  type_options:
                    attr:
                      data-modal-select2: true

I have custom templates for new and edit forms in this entity and @DfinfoEasyAdminExtensionsBundle is a declared twig path :

twig:
    debug: '%kernel.debug%'
    strict_variables: '%kernel.debug%'
    form_themes:
        - bootstrap_3_layout.html.twig
    paths:
        '%kernel.root_dir%/../src/Dfinfo/EasyAdminExtensionsBundle/Resources/views': DfinfoEasyAdminExtensionsBundle`

Also, i give you the trace of the fatal error caused by max execution time exceeded

(1/1) FatalErrorExceptionError: Maximum execution time of 120 seconds exceeded
--
in FilesystemLoader.php (line 80)
at FilesystemLoader->findTemplate('template' => '\'easy_admin/ModalSollicitationInitiale/field_object.html.twig\'', 'throw' => 'FALSE')in Filesystem.php (line 168)
at FilesystemLoader->exists('name' => '\'easy_admin/ModalSollicitationInitiale/field_object.html.twig\'')in FilesystemLoader.php (line 53)
at FilesystemLoader->exists('name' => '\'easy_admin/ModalSollicitationInitiale/field_object.html.twig\'')in TemplateConfigPass.php (line 232)
at TemplateConfigPass->findFirstExistingTemplate('templatePaths' => 'array (0 => NULL, 1 => NULL, 2 => \'easy_admin/ModalSollicitationInitiale/field_object.html.twig\', 3 => \'easy_admin/field_object.html.twig\', 4 => \'@EasyAdmin/default/field_object.html.twig\')')in TemplateConfigPass.php (line 105)

Hope these elements can point in the right direction.

Thanks

Denis

[javiereguiluz]

Thanks for the info. Not sure if this is the cause, but when using the new Twig namespace notation, you must remove the Bundle suffix.

This:

@DfinfoEasyAdminExtensionsBundle/easy_admin/modal.html.twig

should be:

@DfinfoEasyAdminExtensions/easy_admin/modal.html.twig

Update I saw that you define a custom Twig namespace, so this notation is correct (although confusing, and I recommend you to not use Bundle).

[dfinfo]

Hi Javier,

i tried without Bundle in the custom twig namespace but the issue is still here.

I'll try to isolate my entity in an test app and reproduce my customisations step by step. I'll come back to you with my tests result.

For now, i'm stucked at 1.16.12, can't update.

[JoeKre]

@dfinfo Do you have this performance issue only within the EasyAdmin itself? I'm also experiencing a massive performance drop after updating to 1.16.13 but it is not limited to the admin.

For example my homepage in dev environment takes about 550ms according to the debug toolbar with 1.16.12. With 1.16.13 the same page takes 3.5 seconds to load.

According to the built-in profiler the time is spent in Symfony\Component\HttpKernel\EventListener\ProfilerListener

But this seems to happen only once per request. For example my homepage has 2 sub-requests. Only the first sub-request has this long runtime for the Listener, while the master request and second sub request look fine. If there are no sub requests on the page the ProfilerListener of the master request takes the time.

I didn't have the time to investigate this any further for now so i rolled back to 1.16.12 like you but you are definitely not alone with this issue.

Edit: Looking further into it you are right @dfinfo . It all comes down to the changes in TemplateConfigPass. I'm also trying to pinpoint it further within my app.

[JoeKre]

@dfinfo May i know how many entities are managed by easyadmin in your app? I've got 16 in mine. Even though everything slows down with 1.16.13 it still works here on my end.

I think you won't be able to isolate the cause by looking at each entity seperately because the number of managed entities and the lookup change itself are the problem.

[javiereguiluz]

I thank you all for your help trying to find the cause of this problem. However, the only reliable (and super easy) way to find the problem is profiling the app. If you could use Blackfire, Tideways, XHprof or any other tool, that'd be awesome! Thanks.

[dfinfo]

@JoeKre Hi, thanks for asking.

I rely on easyAdmin to build an integrated buisness application for an important client. First features of the app have been delivered to my client now.

I've got 28 entities in my app and "a few" more to come (40 more). There will be 6 or 7 "real" bundles in this modular application that i will package to install via composer. I started a few month ago and still fighting to customize things in EasyAdmin by implementing my EasyAdminExtensionsBundle (ACL, inline add and edit in forms for relations, repositories in entities config...). Till now it is working, means to me that EasyAdmin is a good base, with a good design wich is able to be extended. When i'll have time, i'll try to share my work in EasyAdminExtensionsBundle but for now, it needs refactoring (a lot !).

So, i use quiet a lot of customization (templates, form themes, controllers, overriding, twig_extensions) and it may be one cause of the permformance issue with the number of entities... and with 1.16.13+ !

I don't really know what to do to solve this situation. The problem seems to be related both to EasyAdmin 1.16.13 (the app works fine in 1.16.12) and to the size of the application.

But i can't remove features !

@javiereguiluz I need time to learn how to profile the app to see why there is an issue with 1.16.13+, don't know when i can do that. I'll tell you.

[JoeKre]

@javiereguiluz

Dev Environment with xdebug enabled: https://blackfire.io/profiles/faaf57d1-0ff0-4f31-aa68-aa8e5f42aead/graph

Dev Environment without xdebug enabled: https://blackfire.io/profiles/6cccbd75-85bc-442a-8e5b-4114465fa703/graph

First time using blackfire so i don't fully know what i'm seeing here but maybe you can identify something.

[javiereguiluz]

@JoeKre thanks a lot for providing more info! Sadly, the Xdebug difference distorts the results. It's better to always disable Xdebug when profiling. I'll tell you what I did:

1) I profiled the application in "prod" env and without Xdebug, using EasyAdmin 1.16.12 and 1.16.13:

2) Then, I compared the two profiles as follows:

Comparing the profiles is the key ... because there you'll see which new functions/methods are now called or which part of the application degraded its peformance.

[JoeKre]

No Xdebug here but dev environment:

https://blackfire.io/profiles/19d68cd6-aa50-4ed7-a53f-50dfbbe2dd2c/graph (1.16.12)

https://blackfire.io/profiles/717c7a6b-c082-4f77-9b6e-e702cdc6aa4f/graph (1.16.13)

and the comparison (if the link works): https://blackfire.io/profiles/compare/19d68cd6-aa50-4ed7-a53f-50dfbbe2dd2c...717c7a6b-c082-4f77-9b6e-e702cdc6aa4f/graph

[javiereguiluz]

@JoeKre thanks! That was exactly what we needed. In the comparison, we can see the following:

Now I need to optimize our findFirstExistingTemplate() method. Thanks!

[JoeKre]

@javiereguiluz

No Problem, rather i have to thank you for your work on this awesome bundle :)

[javiereguiluz]

I've been checking this issue and I found a quick solution that works for me, but I'd need you to please verify it yourself. It only requires to change 1 line of code, so maybe you can change it directly in the vendor/ dir and see if it improves performance.

In src/Configuration/TemplateConfigPass.php, the findFirstExistingTemplate() method contains this line:

if ($this->twigLoader->exists($templatePath)) {

Could you please change it as follows?

if (null !== $templatePath && $this->twigLoader->exists($templatePath)) {

[JoeKre]

@javiereguiluz Sure. I'll add the fix first thing tomorrow morning once i'm back in the office and provide a new profile.

[JoeKre]

@javiereguiluz

Here's the profile for the patched version: https://blackfire.io/profiles/39fbd7be-9e8f-4b3d-a8fe-d496426b4a38/graph

1.16.13 unpatched compared to patched: https://blackfire.io/profiles/compare/717c7a6b-c082-4f77-9b6e-e702cdc6aa4f...39fbd7be-9e8f-4b3d-a8fe-d496426b4a38/graph

1.16.12 to 1.16.13 patched: https://blackfire.io/profiles/compare/19d68cd6-aa50-4ed7-a53f-50dfbbe2dd2c...39fbd7be-9e8f-4b3d-a8fe-d496426b4a38/graph

It's an improvement for sure but still noticeable worse then 1.16.12.

Maybe something around this idea may be an option: // 3rd level priority: app/Resources/views/easy_admin/<entityName>/<templateName>.html.twig // 4th level priority: app/Resources/views/easy_admin/<templateName>.html.twig // 5th level priority: @EasyAdmin/default/<templateName>.html.twig

For lookups of 4th and 5th level would it be possible to do a glob of the directory contents and just do the existence lookup against the result instead of going through the TemplateLoader? This way the lookups would only require a hash lookup in the array.

For 3rd level it would be possible to look for existence of the directory before looking up the template, while the directory lookup could also be cached in some way and if necessary even following with the same glob method for the contents as before.

This may not be the best solution but maybe a start in the right direction. What do you think?

EDIT: For 1st and 2nd level some caching for already searched templates may be helpful in real world applications, because some templates might be reused. Nevermind... of course the loader already does implement caching

Greetings Joe

[dfinfo]

@javiereguiluz

i've just tried the patch but it does not solve the issue for me. I still got the max execution time error.

Working on profiling this but got issues with my test server...

Have a good day.

[javiereguiluz]

I've pushed another micro-optimization to #1814. I don't think we can optimize more :(

Before, we didn't really check if a template existed. We just simply called file_exits(...). But that's completely wrong and doesn't always work. A user report made us realize that and that's why we must call the Twig functions to truly check if a template exists.

In any case, keep in mind that you are browsing the app in the dev environment, where this bundle disables all caches (to always execute all the code). In prod environment, this is done once when warming up the cache and reused forever. Could you please profile the application in the prod environment and see if this is true and the performance change is not that noticeable? Thanks!

[JoeKre]

I'll give it a try tomorrow and deliver the results.

The thing is: I get devwill always be slower than prod but it effects all pages (i guess because of the debug toolbar integration). The homepage of my project, which has nothing to do with the easyadmin, at least triples the execution time (with the usual developer setup like xdebug active and die dev environment). That has quite a negative effect on dev experience sadly.

Do you think there's a way to avoid that by skipping the lookups when not actually in the easyadmin part or an option to disable the toolbar integration? That would probably be a viable solution for a lot of people including me.

In @dfinfo s' case where the whole appliaction is built on EasyAdmin that won't help at all :(

[javiereguiluz]

@JoeKre thanks! About the homepage performance issues ... if it's not related to EasyAdmin, I'm not sure it should be affected by the bundle in any way. The best way to find out would be to profile the homepage before/after and make a comparison. Hopefully the reason of the slowdown will be unrelated to EasyAdmin.

[dfinfo]

Here are the profiling results of my app test env with 1.16.12: https://blackfire.io/profiles/5359bd64-6439-488b-be6d-ee914d60215f/graph test env with 1.16.17: https://blackfire.io/profiles/9c28f4ab-83f0-4fd1-a296-966602321c27/graph prod env with 1.16.12: https://blackfire.io/profiles/1c5935cd-1b9d-4f53-be7f-807cfcab1929/graph prod env with 1.16.17: https://blackfire.io/profiles/5d5f8dab-319b-458c-9d93-a416480d015a/graph

test comparison: https://blackfire.io/profiles/compare/16f44e99-fc34-4ebb-9134-963bcd237bf3/graph prod comparison: https://blackfire.io/profiles/compare/70fc8c07-7739-4f55-9fa7-8d6151a5588b/graph

Those profile were made on my test server wich is a minimal LAMP cloud VM (1Gb, 1 CPU). While it is still impossible to make 1.16.17 work on my dev environment wich is composed of Docker containers on my i7, 8Gb Dell XPS13.

@javiereguiluz no performance issue in prod, yes. But this is due to the cache system. I understand that you had to change file_exist() but 1.16.13 code modification in Template location is still implying a big performance loss. I have to work on my dev environment for sure, but for now, i'm still stuck at 1.16.12.

[JoeKre]

Hi Javier.

Here's the new profile for 1.16.13 with both patches applied: https://blackfire.io/profiles/a583a606-da05-4b9e-81f8-d654e7b381b9/graph

And the comparison with 1.16.12: https://blackfire.io/profiles/compare/19d68cd6-aa50-4ed7-a53f-50dfbbe2dd2c...a583a606-da05-4b9e-81f8-d654e7b381b9/graph

Now for the production env profiles:

1.16.13 (patch 1 & 2): https://blackfire.io/profiles/7ca9e156-25b9-4922-80e6-8fa4b01a79c5/graph

1.16.12: https://blackfire.io/profiles/63c43ac0-1c76-485b-a463-315609bfb72c/graph

And compare 1.16.12 to 1.16.13 in prod: https://blackfire.io/profiles/compare/63c43ac0-1c76-485b-a463-315609bfb72c...7ca9e156-25b9-4922-80e6-8fa4b01a79c5/graph

In production there are no concerning issues for sure.

Regarding my homepage performance issue i'm sorry to say the increase in execution time is a result of the easyadmin changes. All dev environment profiles i provided you until now actually were done using the homepage and not within an easyadmin controller. The TemplateConfigPass is in my case always executed within the dev environment, which makes it especially hard because of the missing cache. Isn't the execution of the configpass a result of the integration into the web debug toolbar?

[javiereguiluz]

I've merged the related pull request, but I'll keep this issue open to get more feedback. Thanks!

[JoeKre]

@javiereguiluz

I looked a bit further into the reason why processEntityTemplates is always executed while using dev environment regardless what part of an application gets executed.

Like suspected the reason is found in EasyAdminDataCollector:

public function collect(Request $request, Response $response, \Exception $exception = null)
{
    $backendConfig = $this->configManager->getBackendConfig();
    ....

This leads to all ConfigPasses being processed and executes the template location even when not needed. Do you think there might be a way to prevent the TemplateConfigPass execution for the DataCollector?

[javiereguiluz]

Thanks for looking into this. I don't know if it's going to work ... but I'm going to try to disable this collector for any URL unrelated to EasyAdmin. I'll submit a pull request soon!

[javiereguiluz]

@JoeKre I've just submitted #1821 to solve the problem of EasyAdmin "doing things" even when the request has nothing to do with EasyAdmin.

[JoeKre]

@javiereguiluz

Awesome! Thanks. :) I applied the changes and gave it a short run on my front page:

https://blackfire.io/profiles/compare/a583a606-da05-4b9e-81f8-d654e7b381b9...d52ab2c9-d5be-4d5e-a1ea-a6f9177cc551/graph

Works just fine.

[javiereguiluz]

I'm going to close this as "probably fixed" by #1821. Now that 1.17.1 version has been published, it's easy to test if the changes are working. Thank you all for your help profiling your apps!!