Performance Degraded after update to twig 3.14.2

@themodularlab, could you elaborate on "This is more noticeable on hosting platforms such as Acquia?"

We are hosted on Pantheon, and right now our limited testing doesn't show any noticeable difference on loading the node edit form on the same site running Twig 3.14.0 and 3.14.2.

Can you describe the testing you've done to indicate that it is _more_ noticeable on Acquia, to see if we can replicate on Pantheon?
Is there something specific you suspect about Acquia's architecture versus other platforms where you haven't seen this performance hit?

I have not noticed the degradation other than locally. When xdebug is enabled it's unusable in places, pages like the permission page fail to load (timeout). On environments without xdebug I didn't notice a difference but have not profiled or measured it.

@themodularlab

I guess what I was really getting at was this -- since you said that it seems "more noticeable" on Acquia, that implied to me that there were other hosting environments where it seemed less noticeable to you. Is that actually the case?

Indeed the next step is to profile to find the exact cause.

To keep our eyes on the changes: https://github.com/twigphp/Twig/compare/v3.14.0..v3.14.2

So the difference for twig between these versions is it now loops over any array and checks if any objects inside it are safe to convert to string

But in Drupal we don't do any object specific 'is safe to convert to string' checks because our sandbox policy permits anything that has a __toString method

We can't override the method in the sandbox extension because it's final, so I think we need to propose a PR to symfony for an escape hatch

I checked the logs locally - loading the permissions page on a project (10.3.6) with lots of contributed modules and 8 roles (and with env var XDBEUG_MODE: "off") does show a big difference in response time.

First run on twig 3.14.0

After a drush cr:

"duration":4.943, "cpu_user":42.08,"cpu_system":5.26,"cpu_total":47.34,"memory_peak":135180288

Subsequent load with a warmed cache:

"duration":1.550,"cpu_user":86.44,"cpu_system":5.81,"cpu_total":92.25,"memory_peak":107917312

After updating to twig 3.14.2

After a drush cr:

"duration":14.603,"cpu_user":83.95,"cpu_system":1.78,"cpu_total":85.73,"memory_peak":135180288

Subsequent load with a warmed cache:

"duration":11.857,"cpu_user":97.83,"cpu_system":1.18,"cpu_total":99.01,"memory_peak":107917312

We can't override the method in the sandbox extension because it's final,

Y'all seriously need to consider adding the composer patches plugin and start patching out the final brainrot from upstream.

10 second+ response times up from 1+ second is critical. Do we know if there's already an upstream issue to track this?

I don't see anything at https://github.com/twigphp/Twig/issues, we would probably need to create sample code that demonstrates the issue.

We have some big and complex entity forms in our backend systems. Since the lastest security updates, the loading time of a very important form increased from 1.5 seconds to more than 50 seconds. Way more than factor 10.
Running composer require twig/twig:"3.14.0 as 3.14.2" reduced the loading time to 1.5 seconds again!

From https://github.com/twigphp/Twig/compare/v3.14.0..v3.14.2

I guess the method ensureToStringAllowedForArray might be the culprit (it's a loop and it's recursive) as some Drupal objects are definitely quite big. They tried to fix infinite recursion in 3.14.2, but the fact that objects are traversed might cause the performance issue.

I've opened an MR that shows a possible approach. When we're using our default sandbox policy, we don't need to check to string on any objects, they're all allowed, so can sidestep it altogether.

Haven't tested this and haven't linted either, but see if it helps

Code in the MR is working, site looks as normal and \Twig\Extension\SandboxExtension::ensureToStringAllowed is no longer running. Couple of random fails that I've rerun

🙌 🙌 🙌

Quick test with same project I mentioned in #12 - using twig 3.14.2 and the patch from MR10177 at commit 67bbb312 which applied cleanly to 10.3.6

After drush cr

"duration":4.683,"cpu_user":47.20,"cpu_system":5.98,"cpu_total":53.18,"memory_peak":137277440

(original 3.14.0 duration was 4.943 so back to normal)

Subsequent load with a warmed cache:

"duration":1.559,"cpu_user":86.62,"cpu_system":7.70,"cpu_total":94.32,"memory_peak":107917312

(original 3.14.0 duration was 1.550 so back to normal)

Only did the comparison a couple of times with slight variance in times but certainly appears to resolve the performance issue with no noticeable side effects.

Have not done a thorough code review but good to me - thanks Lee!

I suspect the fails in the pipeline are random fails, but I'm not seeing the button to retry.

Rerunning the fails, the last build was green, so confident they're random

MR is green

We've seen a degraded performance (~20%) on our testing environment since Twig 3.14.2 update as well.

I applied this patch and the performance graphs went back to similar levels as before.

Without patch:

/node/{node}/edit took 2.04sec on average, template.render took 482-720ms
/admin/people/permissions took 9.1sec on average, template.render took 8190-8280ms

With patch:

/node/{node}/edit took 982ms on average, template.render took 121-330ms
/admin/people/permissions took 2.42sec on average, template.render took 1402-1503ms

This looks very nifty. I left one small comment on the MR.

+1

I've addressed the review feedback and created the follow-up #3488584: Simplify RemoveCheckToStringNodeVisitor when Twig 4.0 is released

Hello,
Tested and verified with drupal 11.
MR applied successfully its working as expected.
Check attachments

Can confirm this fixes the issue in Drupal 10.3.9. While I wasn't seeing any performance impacts in most areas of my site the permissions page was completely broken and hit the server timeout whenever I tried to load it. Applying this MR as a patch restores the performance.

This patch contains a snapshot of MR10177 so it can be safely used with composer-patches.

- Code changes makes sense (and are quite ingenious IMHO)
- Seems to work according to the "profiling" comments in here.

Would love to RTBC, the only thing keeping me from doing so is the last commit, which introduced the setting twig_sandbox_allowed_methods to overrule the predefined list of allowed methods.

I think if we introduce a new setting, a commented example should be in web/sites/default/default.settings.php with some comments about what it does.

Then again: n=1, your mileage/opinion may vary, yada yada

@spokje this was already a "hidden" setting, just it's used in two places instead of one now. I think documenting it could be done in a followup.

Thanks @longwave, pulling the trigger

Just another update in regards to performance here (without patch!)

Testing out the 10.3.9 update which includes the 3.14.2 update locally on ddev with a m4 mac mini, loading up the permissions page on a project with a relatively large amount of contrib modules + permissions took about 6 seconds.

The site is hosted on Pantheon and on pantheon, a dev environment before the update was applied was also taking about 6 seconds to load the permissions page.

On a multidev environment with the 10.3.9 update including the twig update, the permissions page now takes 30+ seconds to load.

This wasn't immediately obvious that there was an actual performance issue here (locally) as ddev &/ m4 chip was masking it... but it's very much an issue with the site hosted in Pantheon :)

Tested this on our project at /admin/people/permissions, using network tab:

twig v3.14.0:
- after cr: 3.29s
- next load: 2.58s
twig v3.15.0:
- after cr: 8.39s
- next load: 7.60s
twig v3.15.0 + patch from https://www.drupal.org/i/3487031:
- after cr: 3.27s
- next load: 2.79s

In practice, I did not notice any performance degradation at first. Probably because the form has to be very complex, and the browser itself (UI performance) has to keep up anyway for example for this permission page. But there seems to be quite an impact indeed on a pure PHP performance. This may also behave worse on different environments as others stated.

I also ran the same tests with xhprof and the results are telling, it goes from 3s to 46s to load the page, with a very high wall time on Twig\Extension\SandboxExtension::ensureToStringAllowed.
So +1, looks like it fixes it, thank you!

Looks good. Committed/pushed to 11.x and cherry-picked back through to 10.3.x, thanks!

The commit in #42 would work for 10.2.10 also ?

Please try the attached patch if you have upgraded Twig in 3.14.2 and are seeing the performance regression.

We have released Drupal 11.0.9, 10.3.10 and 10.2.12 today which includes this fix, and therefore avoids having to make the choice between staying on an insecure version of Twig or suffering from performance issues.

@longwave at al thanks very much! We appreciate the effort to do an extra release so we can have our sites both secure and speedy.

We are using the Drupal 10.3.10 and the performance issues are still happening, we are also using Entity browser and after adding 4 or 5 paragraphs it freezes and makes impossible to work.

@roger.bertran have you confirmed that downgrading twig to 3.14.0 makes the performance issue go away? Have you confirmed that your issue is caused by this?

@alexpott after downgrading to twig 3.14.0 the performance issue remains. We've seen that the performance starts to decrease when we work with the entity browser or autocomplete widgets, if we don't interact with these widgets we have no trouble.

@roger.bertran then your issue is unrelated to this specific issue. You need to open a new issue with steps to reproduce and ideally some profiling of your codebase so you can determine where the performance problem is coming from.

@alexpott ok, my bad, thanks for your support!