Enable node render caching

Discussed with @effulgentsia, @Dries, @webchick and others. It's important to expose contrib authors to this concept early and this is going to have an important impact on performance, so we are categorizing this as a beta blocker.

If this is a beta blocker, I'd probably add #2099131: Use #pre_render pattern for entity render caching as well -that's going to affect when certain hooks run and possibly what's available to them just as much as render caching at all.

#drupal8wins! :)

If we have any test failures when all the issues from the OP are committed, we probably need to add some of the manual cache clears from the interdiff in #1605290-135: Enable entity render caching with cache tag support.

Let's try it then.

I don't think we should tag nodes with all their comments. Forum sites for example can have several thousand comments on a single issue, which won't scale - the comment references the node, not vice-versa.

If we had a unique comment thread ID we could tag nodes with that then clear it when a comment in that thread is updated/inserted - might work.

Replying under-the-line ;)

Whether threading is enabled or not, adding new comments/updating/deleting can change what will be rendered on other pages as well - especially when comment threading is enabled but not only. So if we just used a tag for this, something like the comment field name + entity ID would be the closest (i.e. the specific set of comments that the one being added/updated/deleted appears in).

7: enable_node_render_cache-2151459-6.patch queued for re-testing.

As I suspected, we need to bring back a few parts from the interdiff in #1605290-135: Enable entity render caching with cache tag support. I also moved the 'in_preview' special casing to the NodeViewBuilder because this doesn't apply to all entity types.

Drupal\comment\Tests\CommentAnonymousTest will be fixed by #2099105: Clean-up render cache when permission changes

Note sure what's the best way to fix the failures in Drupal\statistics\Tests\StatisticsAdminTest as I'm not familiar with how the statistics ajax thing works, maybe we just need to clear the render cache in the test?

Didn't look into the specific failures, but it case it helps: the AJAX handles collection, but statistics are displayed by PHP. So cached rendered nodes could have stale statistics counts. I think this is fine and we could manually clear the render cache for tests. If someone decides it's not fine at a later point, then it's another use case for #post_render_cache.

1. +++ b/core/modules/comment/comment.module
   +++ b/core/modules/comment/comment.module
   @@ -247,7 +247,6 @@ function comment_field_instance_create(FieldInstanceInterface $instance) {
   
   @@ -247,7 +247,6 @@ function comment_field_instance_create(FieldInstanceInterface $instance) {
     */
    function comment_field_instance_update(FieldInstanceInterface $instance) {
      if ($instance->getType() == 'comment') {
   -    \Drupal::entityManager()->getViewBuilder($instance->entity_type)->resetCache();
        // Comment field settings also affects the rendering of *comment* entities,
        // not only the *commented* entities.
        \Drupal::entityManager()->getViewBuilder('comment')->resetCache();
   

   Not sure why the first one can be removed and the other not?

   Isn't the point of this that there can be comment setting changes that affect how comments are rendered (e.g. changing the pager id) that can't be catched through cache tags?

   And yes, maybe it should be done on all changes.

   If you look at field.module, it currently has tons of calls to clear the field (soon entity) caches, so maybe that should be extended to clear the render cache as well? And possibly move to the entity system with #597236: Add entity caching to core

2. +++ b/core/modules/system/lib/Drupal/system/Tests/System/DateTimeTest.php
   @@ -65,6 +65,7 @@ function testTimeZoneHandling() {
    
        // Set time zone to Los Angeles time.
        $config->set('timezone.default', 'America/Los_Angeles')->save();
   +    \Drupal::entityManager()->getViewBuilder('node')->resetCache(array($node1, $node2));
   

   Not related to this but wondering if there is a reason the API for the render cache resetCache() and the storage is different (just ID's vs. complete objects)?

Oops, I forgot that I need post things under-the-line :D

Re #16:

I'll let @Wim answer that as he's probably more familiar with the statistics stuff. I'm inclined to say that we do want to implement #post_render_cache for view counts.

Re #17:

Not sure why the first one can be removed and the other not?

Because the 'parent' entity (e.g. node) render cache is also tagged with the comment IDs, so it gets cleared by that virtue.

Not related to this but wondering if there is a reason the API for the render cache resetCache() and the storage is different (just ID's vs. complete objects)?

We need the full objects here because we have to get the bundle of the entity. See #1712456-19: How to leverage cache tags in Views :)

15: enable_node_render_cache-2151459-15.patch queued for re-testing.

Rerolled.

[1979468-258] was recently committed. This issue is unblocked now.

22: enable_node_render_cache-2151459-22.patch queued for re-testing.

Rerolled.

The following failed to apply in NodeType.php

// Invalidate the render cache for all nodes.
\Drupal::entityManager()->getViewBuilder('node')->resetCache();

28: enable_node_render_cache-2151459-28.patch queued for re-testing.

28: enable_node_render_cache-2151459-28.patch queued for re-testing.

The test fails noted in #28 for SearchMultilingualEntityTest just passed on my local setup, so I've sent the patch for retesting. Maybe something changed in the matrix and these now pass. I mean, it has been 6 days since those tests were first run.

The Statistics module test failures are indicative of a gap in the drupal_render() testing. I've added what I hope is an additional test that should fail until we've addressed the issue plaguing the Statistics' tests -- namely, that jumping into the render tree midway for an entity (such as when links are rendered from a #prerender function) or when a property of an entity is rendered separately from the top-level node (such as content.links in the node template) causes the post render cache placeholder to be replaced with content and then cached. We want instead for the placeholder to be cached and replaced on render outside of a cache hit.

I simulated jumping into the render tree at the child level with this code:

// Simulate element rendering in a template, where sub-items of a renderable
// can be sent to drupal_render before the parent.
$child = &$element['test_element'];
$element['#children'] = drupal_render($child);
// Render the parent element.
$output = drupal_render($element);

Just a small hunk rejection in comment.module over a conflicting use statement addition.

This should clear up the exceptions.

Interesting, looks like that code path did never run before or works somehow different now.

comment_preview() incorrectly messed with the field on the commented entity, first it got the whole field (field item list), then it set the status, which due to internal defaults/magic ends up on $field->status, and then sets the whole field item list the same way, which also ends up on ->status, so you have $entity->$field->value = $field :)

Maybe the Entity Field API should better handle that and support this but I think the changed code makes more sense anyway, but is unfortunately a bit problematic, apparently:

If I understand it correctly, the new hook now runs after we set the original value back, because it now runs when the render array is rendered. That could be rather unexpected. Maybe we should clone the entity instead, then we don't have to worry about setting back the original value?

comment_preview() incorrectly messed with the field on the commented entity, first it got the whole field (field item list), then it set the status, which due to internal defaults/magic ends up on $field->status, and then sets the whole field item list the same way, which also ends up on ->status, so you have $entity->$field->value = $field

This is EXACTLY the behavior I encountered in #2099131-23: Use #pre_render pattern for entity render caching!! I thought it was something I did or neglected to do in that patch, but now I think it goes deeper.

Please forgive my incorrect use of the ->get/->set, the comment makes it clear what it is supposed to do, and the interdiff at #46 works for me, I wasn't aware that get/set worked differently. I am now. Thanks.

I can reproduce, but only when I execute the tests with run-tests.sh. Not sure what's going on there, but the translations are somehow switched, the 0/1 keys there.

The patch no longer applied: here's a plain reroll as I am seeing warnings all over the place. Let's see what the bot says.

Not sure what went wrong with the previous patch, but this one should have less warnings :)
Now I am looking at the test failures for reals...

This should fix the multilingual search failures. Sorry for breaking other stuff, but I really have no time to work on core these days. I think this interdiff can be applied to a saner reroll to make everything green :)

However we might need more test coverage actually as the root cause was cache key not including language. Surprisingly test failed when run by an anonymous user (this is why locally they pass with the Simpletest UI), I am wondering whether that's somehow related to the role granularity.

Core moves fast these days...

As you can see the SearchMultilingualEntities failures are gone, so the interdiff in #59 should be good :)

The last patch looks pretty good to me. I won't comment on the post_render_cache parts to not derail this issue, and I only found one thing that doesn't seem right:

+++ b/core/modules/comment/lib/Drupal/comment/Entity/Comment.php
@@ -191,6 +190,13 @@ public static function postDelete(EntityStorageControllerInterface $storage_cont
+  public function referencedEntities() {
+    return array($this->getCommentedEntity());
+  }

Why are we excluding any other reference fields that might exist on a comment entity? See what the parent method does.

+++ b/core/modules/comment/lib/Drupal/comment/Entity/Comment.php
@@ -190,6 +190,13 @@ public static function postDelete(EntityStorageControllerInterface $storage_cont
    */
+  public function referencedEntities() {
+    return array($this->getCommentedEntity());
+  }

This should include the parent/default implementation too? The comment might have an entity reference field and has an author and so on...

We might also want to add a todo to add a, possibly computed field that does expose the entity as a field, so that the generic code can deal with it, that's currently however blocked on #2114707: Allow per-bundle overrides of field definitions.

... Yeah, I can see that it too me too long to post this as i got distracted again, @amateescu basically said the same :)

This is a quick xhprof comparison of a single article (node/1) page load in a standard install. The first table is the page load, the second just the drupal_render function.

Inclusive wall time improves significantly overall as one would expect with aggressive caching turned on. Exclusive wall time for drupal_render increases as, I assume, this function is now doing more work to assemble the cached output. Maybe, just a guess there :) But the increase is negligible.

And we should be able to get these numbers even lower for a warm cache with #2099131: Use #pre_render pattern for entity render caching.

I reviewed this and found nothing to complain about. The performance gain is substantial.

w00t w00t!! :) Sending over catch's way.

The improvement is great but the overall numbers are horrible, three seconds for a simple node page is worse than Drupal 7 ever got iirc. At least this gives us a good opportunity to see what's left on a warm cache now, and there's still the #pre_render patch to go too.

I haven't reviewed latest patch yet, would be interesting to see Wim's numbers too but won't block a commit on it.

Few minor things.

1. +++ b/core/includes/common.inc
   @@ -4284,8 +4284,19 @@ function _drupal_render_process_post_render_cache(array &$elements) {
   + * Therefor, drupal_render_collect_post_render_cache() must be called *before*
   

   Therefore.

2. +++ b/core/modules/comment/lib/Drupal/comment/Entity/Comment.php
   @@ -37,7 +37,6 @@
   - *   render_cache = FALSE,
   

   whooo.

3. +++ b/core/modules/node/lib/Drupal/node/Entity/Node.php
   @@ -40,7 +40,6 @@
   - *   render_cache = FALSE,
   

   whoo.

4. +++ b/core/modules/node/lib/Drupal/node/Entity/NodeType.php
   @@ -196,6 +196,9 @@ public function postSave(EntityStorageControllerInterface $storage_controller, $
   +      \Drupal::entityManager()->getViewBuilder('node')->resetCache();
   

   How come?

   And do we need to clear the node type above if we clearing all nodes?

5. +++ b/core/modules/system/lib/Drupal/system/Tests/Common/RenderTest.php
   @@ -804,18 +804,26 @@ function testDrupalRenderRenderCachePlaceholder() {
   +    $this->assertTrue($nodes->length > 0, 'The token attribute was found in the cached markup');
   

   Just assertTrue($nodes->length) no?

6. +++ b/core/modules/system/lib/Drupal/system/Tests/Common/RenderTest.php
   @@ -804,18 +804,26 @@ function testDrupalRenderRenderCachePlaceholder() {
   +    if ($nodes->length > 0) {
   

   Same again.

This patch also needed a reroll.

+++ b/core/includes/common.inc
@@ -4284,8 +4284,19 @@ function _drupal_render_process_post_render_cache(array &$elements) {
+ * Therefor, drupal_render_collect_post_render_cache() must be called *before*
Therefore.

Fixed.

+++ b/core/modules/system/lib/Drupal/system/Tests/Common/RenderTest.php
@@ -804,18 +804,26 @@ function testDrupalRenderRenderCachePlaceholder() {
+ $this->assertTrue($nodes->length > 0, 'The token attribute was found in the cached markup');
Just assertTrue($nodes->length) no?

Zero evaluates to false in PHP, so yes, the great than check is superfluous. Removed.

+++ b/core/modules/comment/lib/Drupal/comment/Entity/Comment.php
@@ -37,7 +37,6 @@
- * render_cache = FALSE,
whooo.

Agreed. Amaze. Such cache.

+++ b/core/modules/node/lib/Drupal/node/Entity/NodeType.php
@@ -196,6 +196,9 @@ public function postSave(EntityStorageControllerInterface $storage_controller, $
+ \Drupal::entityManager()->getViewBuilder('node')->resetCache();
How come?

And do we need to clear the node type above if we clearing all nodes?

I do not know. Leaving to Wim to chime in. Hopefully he remembers whey this code was added.

cache can no longer be called as a global function.

cache() to \Drupal::cache()

@#70: Hm, not sure how you got those numbers, is it possible that the before is a cold start that needs to build up caches? There's no way that we could go down from 440k function calls to 86k just with this?

Did some runs myself, these are the numbers I came up with:

- node/1 with an article with a few tags, image, body and comment form.
- PHP 5.5 with opcache. Optimized MySQL and *fast* hardware.
- xhprof with only the memory flag (cpu is a huge overhead), enabled through devel.module, so we're missing the early bootstrap stuff, but that doesn't change anyway.
- I also had to patch xhprof to not track php functions as it segfaults otherwise on 5.5. I'm not sure how it exactly affects the results, probably at least the number of function calls is missing them, so I also did some good old ab tests to cross-check the numbers
- Logged in as uid 1

Full:

drupal_render()

There's a lot of post render cache stuff going on, so I closed comments and tested again.
Full:

drupal_render()

ab -n 100 -c 1 http://d8/1:

HEAD:

Requests per second:    6.52 [#/sec] (mean)
Time per request:       153.487 [ms] (mean)

Patched:

Requests per second:    7.37 [#/sec] (mean)
Time per request:       135.672 [ms] (mean)

=> 12% faster.

Numbers are pretty stable, I did multiple runs. As mentioned, xhprof wasn't covering the bootstrap part, so that should explain why those numbers are almost the same.

Because I usually can't stop when I start to profile stuff, here are some additional notes/experiments:

10% is spent in two calls to entity_create(), one due to EntityDisplayBase::getFieldDefinitions() and one in user_attach(). The first is going away in #2114707: Allow per-bundle overrides of field definitions, the second I'm not sure, can possibly be optimized to at least only run when we actually need it, it's only used as a fallback when a user can't be loaded.

Also, with a temporary hacked together combination of this, #597236: Add entity caching to core, #2182239: Improve ContentEntityBase::id() for better DX, #2114707: Allow per-bundle overrides of field definitions and removing the entity_create() in user_attach_accounts() I'm down to 118ms. One other thing is the mentioned pre_render() issue for running field formatters. While we certainly still have a lot to do, I have a feeling that Entity Field API is going to be pretty well optimized compared to to other parts at that point.

Need. to. stop. and. go. to. bed. :)

Arg. Just noticed that I had xdebug + xhprof enabled, xhprof becomes much slower when xdebug is enabled. Relatively, the numbers should still be ok'ish, although fewer function calls might suggest more improvements than there actually are.

So just a few quick numbers, disabling xdebug, xhprof, devel, enabling apc classloader and then the same ab tests again:

HEAD:

Requests per second:    16.89 [#/sec] (mean)
Time per request:       59.213 [ms] (mean)

With this patch:

Requests per second:    19.23 [#/sec] (mean)
Time per request:       52.003 [ms] (mean)

With my fun issue mix-up from above, I'm getting this:

Requests per second:    21.40 [#/sec] (mean)
Time per request:       46.723 [ms] (mean)

Before you get too excited about that, here's the same for D7 node/1:

Requests per second:    67.70 [#/sec] (mean)
Time per request:       14.771 [ms] (mean)

So still 3x slower.

OK that looks a lot more like I was expecting on the profiling.

We should dsm() every comment submission that mentions xhprof with 'did you warm the cache both times and did you disable xdebug?' :P

Regarding + \Drupal::entityManager()->getViewBuilder('node')->resetCache(); in NodeType.php: amateescu added that in #15. I don't remember the specifics, but AFAICT it's there because NodeType != Node, yet NodeType affects Node. Therefor, a change in a NodeType config entity (i.e. node entity bundle, e.g. "article") should cause the cache entries tagged with nodes of that type to be cleared. But we don't create cache tags for each node type (i.e. node entity bundle, e.g. "article"), therefor we must reset the Node's view builder's cache completely.
(I hope I didn't make any mistake in that reasoning — it's been a long day and I've been on the train for hours and still am.)

The reasoning sounds right, we might want to revisit those very high level cache tags a bit, but since the patch only introduces the tag invalidation that's plenty for me.

Committed/pushed to 8.x, thanks!

#81/ab was done with anonymous users, but without page or block caching enabled.

This broke comment stubbing. #2207907: Comment stubbing is broken