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?

@gravelpot

We haven't done any official performance testing but rather this is something observed by myself and my clients. Prior to updating to 3.14.2, page load times were pretty normal. After 3.14.2, our page load for a node edit form can be well over 30 seconds. We are building a new site so there is very little content at this point. As a test, I downgraded back to 3.14.0 and page load times returned to normal.

There may be some server settings in place on our Acquia env that could be partially contributing to this but also the performance and page load times return to normal when downgrading back to 3.14.0.

Based on this part of the 3.14.2 patch, it looks like they're recursing through everything even before trying to render it?

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?

@gravelpot,

I have only personally observed on a local env and via Acquia. I have seen others reporting similar issues but unsure of what hosting they are using.

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 with several contribute 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 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!

Applying the patch from MR10177 on 10.3.8 is also showing improvements for me. I have only tested locally but will be pushing to a dev environment soon so I can report back later. But so far so good!

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.

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 📌 Simplify RemoveCheckToStringNodeVisitor when Twig 4.0 is released Active

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.