Currently, DFP generates tag data on every page request, and every tag generated calls token_replace(). Unfortunately, token_replace() Is surprisingly slow as it calls every hook_tokens() implementation for every call, and every hook_tokens() implementation has to do all of its work regardless of whether it will be used or not. That is adding considerable time to every page load on my site. This is sad. :-(

I'm fairly certain that we can improve the speed of generating tokens with some intelligent caching. Baring that, since the replacements do not change we can at the very least dissect token_replace() and do a more performant implementation. There's a lot of potential for performance benefits here.

I'm going to take a crack at doing so, but wanted this issue here as notification. Stay tuned for a patch once I have one.

Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Crell’s picture

Status: Active » Needs review
FileSize
4.16 KB

And patch. I ended up doing custom caching around token_replace(), since in this case the replacement values are predictable and we have deep knowledge about them. The next result is that we can (I'm fairly certain) rely on just the incoming text and a few IDs as a cache key and that will be reliable. When a value is updated the cache will be cleared anyway and the replacements get regenerated.

Crell’s picture

FileSize
4.97 KB

Revised patch that catches more cases.

Status: Needs review » Needs work

The last submitted patch, 2: 2468531-caching.patch, failed testing.

Crell’s picture

I was just reminded by FabianX in IRC that node save does NOT clear all caches, just the page/block cache. So we'll need to do some manual cache clearing her as well. Alternatively, use entity_modified module to get a key that is unique for every object. For nodes we could just use the updated time to get uniqueness but that wouldn't cover users, terms, or tags.

bleen, I don't know if you're OK with adding a module dependency for performance... Please advise.

bleen’s picture

I dont love the idea of adding a new dependency .... can it be added optionally (e.g. if (module_exists(...)) {...})?

Crell’s picture

In that case, the caching would only be available if that module were installed. That would presumably need to be documented somehow. If it's not installed then the new function would just sub-call straight to token_replace().

Given the performance impact, though, I'd think everyone would want to have it installed. token_replace() is just way too slow to call on every page.

bleen’s picture

Given the performance impact, though, I'd think everyone would want to have it installed. token_replace() is just way too slow to call on every page.

Fair...

Do we have an idea of how big a performance improvement are we talking about here?

Crell’s picture

I just ran some benchmarks of the similar patch for SiteCatalyst, and the difference was about 260 ms (aka, huge): #2468647-2: tokens regenerated on every request, very slow. I suspect the difference here would be in the same ballpark.

If that's the case, then between these two modules, we're looking at shaving a half-second off of page loads. That's definitely worth a new dependency, IMO.

bleen’s picture

If that's the case, then between these two modules, we're looking at shaving a half-second off of page loads. That's definitely worth a new dependency, IMO.

I cant really argue with that...

/me stands ready to review a passing patch with new dpendency (on both issues)

Crell’s picture

Status: Needs work » Needs review
FileSize
6.25 KB

Well, this is troublesome. Here's the latest patch for DFP. It's not passing all tests, but neither is the current 7.x-1.x branch on my test system. I am not sure what the issue is. Suggestions welcome.

Status: Needs review » Needs work

The last submitted patch, 10: 2468531-caching.patch, failed testing.

Crell’s picture

And when I spin up a brand new, fresh Drupal 7 site to test this on, I get full test passage both with and without this patch. Again, I suspect it's related to the new dependency.

bleen’s picture

While in a boring meeting I ran the DFP tests on simplytest.me (with the new dependency installed) and there were 2 failures. I'm not sure there isnt something else weird going on here.

Crell’s picture

Status: Needs work » Needs review
FileSize
7.13 KB

Revised version. This now sets the cache item separately per path to avoid the one cache item becoming ginormous. It also adds a config variable to allow the cache to be persisted longer than the next system cron. (It's X seconds, plus the next system cron. X defaults to 0.)

Unfortunately I have no further time on this client project to work on it, and this is working for us locally. So unless it fails for us for some reason I have to bail out here. bleen, hopefully you can carry it on home.

Status: Needs review » Needs work

The last submitted patch, 14: 2468531-caching.patch, failed testing.

Status: Needs work » Needs review

bleen18 queued 14: 2468531-caching.patch for re-testing.

Status: Needs review » Needs work

The last submitted patch, 14: 2468531-caching.patch, failed testing.

bleen’s picture

I have been trying to figure out the simpletest issue here and its making my brain hurt. I do get test failures when I run simpletest via drush:

```drush test-run dfpAdCategoriesTest --uri=local.d7```

But the errors I get are around a failure by the "admin_user" to log in as opposed to the "module enable" failure in the simple test her on D.O.

All tests pass when I run them via the GUI and all tests are now passing when I run them via the GUI on simplytest.me (s long as I run them one at a time... if I try and run all the DFP tests I get generic failures that seam to suggest that simplytest.me does not like when the batch api runs for a while)

Status: Needs work » Needs review

bleen18 queued 14: 2468531-caching.patch for re-testing.

Status: Needs review » Needs work

The last submitted patch, 14: 2468531-caching.patch, failed testing.

bleen’s picture

Status: Needs work » Needs review
FileSize
7.58 KB

Trying to explicitly enable the entity_modified module. See if that makes testbot happy

Status: Needs review » Needs work

The last submitted patch, 21: tokens_regenerated_on-2468531-21.patch, failed testing.

bleen’s picture

I have it on good authority (@davereid) that once I commit this and create a new release, then testbot will be happy again. Giving it a whirl.

Comiting this patch which is identical to the one in #14 except for a few comments.

bleen’s picture

To test, I am going to wait unitl there is a new dev release to see if that works. If not I will create a new tag tomorrow

  • bleen18 committed 93b79cb on 7.x-1.x authored by Crell
    Issue #2468531 by Crell, bleen18: fixed tokens regenerated on every...
bleen’s picture

Status: Needs work » Needs review

... lets see if testbot is happy now

Status: Needs review » Needs work

The last submitted patch, 23: tokens_regenerated_on-2468531-23.patch, failed testing.

bleen’s picture

Status: Needs work » Fixed

it looks like testbot really does need a new release to pickup new dependencies. Sigh

Status: Fixed » Closed (fixed)

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

marcelovani’s picture

Regarding the patch committed above, I am a bit concerned about the effects on large websites, specially when they share the same database and memcache.

+++ b/dfp.module
@@ -838,6 +835,95 @@ function _dfp_prepare_adunit($tag) {
+  $cache_item = DFP_TOKEN_CACHE . ':' . current_path();

One of the things that makes me concerned is the number of entries on the cache, since a cache per page is being used and all the ad tags are stored many times, due to the combination of the keys.

+++ b/dfp.module
@@ -838,6 +835,95 @@ function _dfp_prepare_adunit($tag) {
+}

It is still not clear to me why we need to use the Entity Modified module, which will do extra queries on every page. Even though the query is very fast, on a large scale, it could be quite substantial. Normally when we render tokens, we pass the data as second parameter, which doesn’t require any extra query, i.e. current node or current user.

I see that the cache is keyed by uid, which would only be relevant to websites that have authenticated users. For websites that have only anonymous users and varnish in front, all of these customisations become redundant, that said, this new functionality could be at least optional.

Here is some benchmarking I did comparing DFP 1.3 vs DFP 1.4, please shout if I missed anything:

  1. Install Drupal 7.39 (Standard profile)
  2. Install Ctools
  3. Install Token
  4. Install Devel Generate
    1. Generate content (admin/config/development/generate/content)
    2. Create a new user (admin/people/create)
    3. Edit content type Article and add field_colors (Type text. Allow unlimited values)
  5. Install DFP 1.3
    1. Configure dfp (admin/structure/dfp_ads)
    2. - Network id 999
    3. - Dafault ad unit pattern" [user:uid]
    4. - Global Targeting
    5. - title = [node:title]
    6. - color = [node:field_colors]
    7. Create 4 DFP ad tags admin/structure/dfp_ads
    8. Place dfp blocks admin/structure/block
  6. Install xhprof
  7. Clear cache
    - Visit a node
    - View xhprof results (Wall time)
    - First run
    - Main 1.216,030
    - template_preprocess_dfp_tag 29,605
    - Second run
    - Main 427,636
    - template_preprocess_dfp_tag 15,932
    - Third run
    - Main 319,582
    - template_preprocess_dfp_tag 26,837
    - Average
    - Main 654,416
    - template_preprocess_dfp_tag 24,124
  8. Install Entity modified
  9. Updage DFP to 1.4
  10. Clear cache
    - Visit a node
    - View xhprof results (Wall time)
    - First run
    - Main 1.192,287
    - template_preprocess_dfp_tag 49,398
    - Second run
    - Main 387,619
    - template_preprocess_dfp_tag 6,239
    - Third run
    - Main 290,247
    - template_preprocess_dfp_tag 6,028
    - Average
    - Main 623,384
    - template_preprocess_dfp_tag 20,555

Here is what is stored into the cache table:

First time we look at the node as admin user

drush cg dfp:tag_token_results:node/13
stdClass Object
(
    [cid] => dfp:tag_token_results:node/13
    [data] => Array
        (
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|1-1] => Blue, White
        )

    [created] => 1443445302
    [expire] => 1443446302
    [serialized] => 1
)

Visit node as anonymous user and check the cache again, now we have twice as many entries for that node

curl http://dfptest.vm.didev.co.uk/node/13
drush cg dfp:tag_token_results:node/13
stdClass Object
(
    [cid] => dfp:tag_token_results:node/13
    [data] => Array
        (
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|1-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot1-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot2-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot3-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot4-1] => 999/not yet assigned
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|0-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|0-1] => Blue, White
        )

    [created] => 1443445594
    [expire] => 1443446594
    [serialized] => 1
)

Re-save node and view the cache

drush cg dfp:tag_token_results:node/13
stdClass Object
(
    [cid] => dfp:tag_token_results:node/13
    [data] => Array
        (
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|1-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot1-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot2-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot3-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot4-1] => 999/not yet assigned
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|0-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|0-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443445616|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443445616|1-1] => Blue, White
        )

    [created] => 1443445616
    [expire] => 1443446616
    [serialized] => 1
)

View node as anonymous and check cache

drush cg dfp:tag_token_results:node/13
stdClass Object
(
    [cid] => dfp:tag_token_results:node/13
    [data] => Array
        (
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|1-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot1-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot2-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot3-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443444016|0-1|slot4-1] => 999/not yet assigned
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443444016|0-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443444016|0-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot1-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot2-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot3-1] => 999/1
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|1-1|slot4-1] => 999/1
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443445616|1-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443445616|1-1] => Blue, White
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|0-1|slot1-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|0-1|slot2-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|0-1|slot3-1] => 999/not yet assigned
            [eb69b6658cfce2d9b2f5997aa04878267bbbca63|13-1443445616|0-1|slot4-1] => 999/not yet assigned
            [4d3801b4c5fdabf271953787920792be8068fdad|13-1443445616|0-1] => Obruo Pneum Premo Probo
            [add7a34f360c289772dfc4074a620846b3b0acd3|13-1443445616|0-1] => Blue, White
        )

    [created] => 1443445643
    [expire] => 1443446643
    [serialized] => 1
)

On a large site, with thousands of nodes being updated and viewed every day, the cache would be massive.
@Crell, I don't see a problem with token replacement, do you think that could be some of the other custom modules used by your client that had some bad logic and made token replacement slow?

@bleen18 Since we use Varnish here and do not have any indication of problems with token replace being slow, do you think it would be a good idea to make this functionality optional?

osopolar’s picture

Status: Closed (fixed) » Needs review

Reopening issue as it seems that #30 didn't get any attention. Or should that be a follow up?

Crell’s picture

Status: Needs review » Fixed

Yes, it's generally better to open a new issue and reference this one when the closed issue is this old.

Status: Fixed » Closed (fixed)

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