This snippet below is an email body that I am running through token->replace.

It runs for a long time until timeout. with max_execution_time of 60 it also failed.

With some trial and error removing the last 7 tokens makes it work OK, and adding one by one starts to increase the time needed exponentially.

There's some unnecessary recursion going on.

I attempted to fix the problem, but the code is rather complex as it goes over many many things to properly understand.

I will provide a patch that fixes this and potentially increases performance a lot for these cases, but it's not really a fix for the issue, but rather a workaround that prevents the issue for propagating.

As you can gather from the tokens, there are quite a bit of chain tokens involved.

Details:

Content ID: [node:nid]
Request Detail: [node:field_requestdetail]
First name: [node:field_shiptofirstname]
Last name: [node:field_shiptolastname]
Address: [node:field_shiptoaddress]
City: [node:field_shiptocity]
State: [node:field_shiptostate]
ZIP: [node:field_shiptozip]
Country: [node:field_shiptocountry]
Phone: [node:field_shiptophone]
Status: [node:field_status]

Details for registered product:

Content ID: [node:field_registered_product:entity:nid]
Part Number: [node:field_registered_product:entity:field_product:entity:field_partnum]
Serial Number: [node:field_registered_product:entity:field_serial_number]
Purchase Date: [node:field_registered_product:entity:field_purchase_date:date:long]
Registration Date: [node:field_registered_product:entity:field_registration_date:date:long]

Details for User

User ID: [node:field_registered_product:entity:field_user:entity:uid]
Username: [node:field_registered_product:entity:field_user:entity:name]
Mail: [node:field_registered_product:entity:field_user:entity:mail]
First name: [node:field_registered_product:entity:field_user:entity:field_firstname]
Last name: [node:field_registered_product:entity:field_user:entity:field_lastname]
Address: [node:field_registered_product:entity:field_user:entity:field_address]
City: [node:field_registered_product:entity:field_user:entity:field_city]
State: [node:field_registered_product:entity:field_user:entity:field_state]
Zip: [node:field_registered_product:entity:field_user:entity:field_zip]
Country: [node:field_registered_product:entity:field_user:entity:field_country]
Phone: [node:field_registered_product:entity:field_user:entity:field_phone]
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

hanoii created an issue. See original summary.

hanoii’s picture

Issue summary: View changes
Status: Active » Needs review
FileSize
493 bytes

Attached is the patch. It's very simple, basically it's preventing an iteration if the replacement is already there.

hanoii’s picture

FileSize
917 bytes

Well, this is really a duck-taped patch. I also found out that if the replacement of any of the fields is not replaced (like for if the field is empty), the root issue propagates anyway as the recursion happen.

The following patch makes sure that doesn't happen but setting a replacement to blank. This is only done if $options['clear'] is set.

While I was OK with the patch in #2, this one is likely not the way to fix this. But I still leve the "Needs review" as worth a review.

Status: Needs review » Needs work

The last submitted patch, 3: 2905735-n3.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

Berdir’s picture

Can you provide some more information in what level/token it exactly starts to loop and how? And a test for this would nice.

Sounds like it might be related to multiple nested tokens on the same field in a single text.

hanoii’s picture

FileSize
1.42 KB

Better ducktaped patch, with an even further improvement.

Will reply to you @Berdir on another comment.

hanoii’s picture

@Berdir so, I wanted to provide more context for this. Let's see if the attached debug files help, but it's a very odd issue. I still don't understand it.

It doesn't seem as a recursion loop, if what I did is OK, but rather something is messing the iteration altogether.

If you remove the last 6 tokens, it "works". It still takes a lot but at least I was able to use that to add some debug messages.

See the patch attached that shows what I am attempting to record and how.

I honestly don't quite get it. Maybe I am attacking it wrongly (it's late here) but with a fresh look and being more familiar with the code you might be able to help better.

I am attaching the following debug files:

References:

(S): The provided sample text on the issue summary without the last 6 tokens.
(C): All of the tokens provided on the issue summary
  • drupal_debug-loop-replacements.txt: (S) Original code - ~6400 calls to field_tokens()
  • drupal_debug-first-continue: (S) With only the first continue added by the patch on #6 - ~ 1200 calls to field_tokens()
  • drupal_debug-first-second-continue.txt: (S) With both continue (but not the blank tokens) added by the patch on #6 - ~ 272 calls to field_tokens()
  • drupal_debug-first-second-continue-all-tokens.txt: (C) With both continue (but not the blank tokens) added by the patch on #6 - ~ 14600 calls to field_tokens()
  • drupal_debug-patch-n6: ~14 calls to field_tokens

You see that without the continues it was around 6400.

With the continues it went down to 272.

Once I added all tokens and without the setting of the replacement of the blank tokens it went from 272 to 14600.

Although you can see on the patch, the logs shows a line of the format:

$count-(entity|field)-$original => $level

$count and $level are static vars attempting to count and spot recursive issues, although $level is always reasonable.

$original is the token

And entity or field is just a label I choose to differentiate the two different token foreachs.

Hope this helps.

hanoii’s picture

Jax’s picture

This indeed dramatically improves performance of replacing chained tokens. And it seems everything keeps working. Now all that is left is understand why.

Yury N’s picture

Faced the same issue. Re-rolling patch from #6 against current 8.x-1.x

nikitagupta’s picture

Assigned: Unassigned » nikitagupta
nikitagupta’s picture

Assigned: nikitagupta » Unassigned
Status: Needs work » Needs review

#9 Patch applied cleanly.

Berdir’s picture

Finally found some time and motivation to look into this. Can reproduce the problem.

The basic problem is that we loop over tokens one by one *but* \Drupal::token()->findWithPrefix() works on all tokens and is not meant to be used in a loop, which is a bit tricky as we need to know if there are field tokens and for which field. So it looped over all tokens and each loop found all tokens for the same field. And if you have 2-3 such references then you get that nice exponential growth of nested calls.

I tried to address this at the root with two changes:

1. I'm filtering out all identified $field_tokens that are already in $replacements.
2. That alone won't prevent repeated calls on the nested levels because those don't have the $replacements yet as that is not shared between nested calls. So I check it to call the found tokens one-by one. There is a bit of overhead with that, but in my testing, it is clearly more efficient as we don't have to worry about multiple matches. Thought about even calling field_tokens() directly and skipping the hook over all token hooks + alter.

Additionally, I also noticed that we might be trying to load the same view display a lot and added a static cache for that and only attempt to load it if we need it. I suspect that will cause some issues with tests. Might drop the static cache again, would likely require a ton of fields that are rendered through the formatter to make that worth it and then you have different problems.

I think this will also help with metatag a bit, e.g. when you are using image + width/height tokens of an image field on a media reference of a node.

To test/reproduce, I simplified it a bit to use a media reference field on a media entity, with a reference to itself, so I can repeat as many "nested" fields as I want. And then the following script:

use Drupal\media\Entity\Media;

$media = Media::load(1);

$token_text = '
mid: [media:field_foo:entity:field_foo:entity:field_foo:entity:mid:value]
bundle: [media:field_foo:entity:field_foo:entity:field_foo:entity:bundle:target_id]
vid: [media:field_foo:entity:field_foo:entity:field_foo:entity:vid:value]
created: [media:field_foo:entity:field_foo:entity:field_foo:entity:created:value]
langcode: [media:field_foo:entity:field_foo:entity:field_foo:entity:langcode:value]
name: [media:field_foo:entity:field_foo:entity:field_foo:entity:name:value]
status: [media:field_foo:entity:field_foo:entity:field_foo:entity:status:value]
uuid: [media:field_foo:entity:field_foo:entity:field_foo:entity:name:value]
';

echo \Drupal::token()->replace($token_text, ['media' => $media]);

on HEAD, that takes 26s for me. With the patch, it's 0.2s and that's including the drupal bootstrap, measuring with "time drush scr foo.php" The example might be a bit extreme, but it's not too far off from those commerce use cases.

Status: Needs review » Needs work

The last submitted patch, 13: token-field-token-performance-improvements-2905735-2.patch, failed testing. View results
- codesniffer_fixes.patch Interdiff of automated coding standards fixes only.

Berdir’s picture

Thought so, dropping the static cache from that for now but keeping the function.

Also, forget the part about metatag, that would only apply when rendering multiple token for a single metatag.

  • Berdir committed 492f684 on 8.x-1.x
    Issue #2905735 by hanoii, Berdir, Yury N: Replacing a lot of chained...
Berdir’s picture

Status: Needs review » Fixed

Lets hope this doesn't introduce any regressions, really want to have this in a release.

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.