Add render_cache debug output

I'd love this!

I added the config option 'cache_debug' in services.yml. I also attempted to print the debug data (I omitted cache_info for debugging reasons). When I receive a cache miss, everything works as expected, but when there's a cache hit it doesn't work as I hope it would.

I guess I miss something here...

Good progress here, thanks :)

1. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -67,6 +67,7 @@ public function renderRoot(&$elements) {
   +    $twig_service = \Drupal::service('twig');
   

   This service should be injected.

2. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -130,6 +131,12 @@ public function render(&$elements, $is_root_call = FALSE) {
   +          \Drupal::logger('render')->notice('Wrapping with cache debug data on cache GET.');
   

   This is just temporary debug output, while working on this, right? :)

3. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -316,6 +323,10 @@ public function render(&$elements, $is_root_call = FALSE) {
        if (isset($elements['#cache'])) {
          drupal_render_cache_set($elements['#markup'], $elements);
   +      if ($twig_service->isCacheDebug()) {
   +        \Drupal::logger('core')->notice('Wrapping with cache debug data on cache SET.');
   +        $elements = $this->addDebugOutput($elements, FALSE);
   +      }
   

   This is why the debug output is only appearing for you in case of a cache miss: this is the code path that deals with a cache miss and writing to the cache.

   You'll also want to call it in this if-test, where a render cache hit is handled:

       // Try to fetch the prerendered element from cache, run any
       // #post_render_cache callbacks and return the final markup.
       if (isset($elements['#cache'])) {
         $cached_element = drupal_render_cache_get($elements);
         if ($cached_element !== FALSE) {
   …

4. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -387,4 +398,22 @@ protected function processPostRenderCache(array &$elements) {
   +  }
    }
   

   Needs a newline between these two braces.

+++ b/core/vendor/twig/twig/lib/Twig/Environment.php
@@ -94,11 +94,13 @@ public function __construct(Twig_LoaderInterface $loader = null, $options = arra
+            'cache_debug'         => false,

A matching default value in default.services.yml is still missing for this.

But… this actually doesn't belong in Twig. Twig is a theme engine. It's pluggable. Somebody could replace it.

This render cache debug output is independent of Twig. We probably want a renderer.config parameter in default.services.yml, just like we have twig.config. And in there, we'd then have a debug: false, just like for Twig.

Added a renderer.config array, injected it into the Renderer object and changed the way how the config variables are accessed.

Still stuck on where to put the $this->addDebugOutput code, it seems to never hit the cache and I don't know why ... need help :-)

Oh, and the addDebugOutput() method still needs work, i know :-)

I tested the patch and found a few important problems:

1. if you have an structure like ['parent' => ['#type' => 'container', '#cache' => […], 'child' => ['#markup' => 'this is the child', '#cache' => […]]]], then the child element's cache debug output is render cached. We don't want that, because then the cache debug output is no longer reliable: it'll continue to say that the child is retrieved from cache (or not), despite the child not having been retrieved separately at all; it's only the parent that was retrieved from render cache, not the child!
2. Secondly, the issue title specifically says "render cache debug output". I.e. it should only affect those parts of the render array that are intended to be cached. But in the current implementation, every single level of every render array always gets this debug output. That results in too much debug output. You'll want to only show debug output for those elements that may be render cached, basically if (isset($elements['#cache']['cid']) || isset($elements['#cache']['keys']).

can you point to the issue where you had that conversion to saveToCache / retrieveFromCache, because I don't remember.

The debug output really belongs in those functions.a

Agreed.

The patch you're looking for is at #2379741: Add Renderer::getCacheableRenderArray() to encapsulate which data is needed for caching a render array and have views use it.

Applied patch #2379741: Add Renderer::getCacheableRenderArray() to encapsulate which data is needed for caching a render array and have views use it + rerolled parts of previous patch and printing cache tags and keys (see interdiff).

I've been pushing #2379741: Add Renderer::getCacheableRenderArray() to encapsulate which data is needed for caching a render array and have views use it further, to unblock this issue.

The patch in #11 that's marked as "do-not-test" should actually not be marked as "do-not-test". There should be a version of the patch that does NOT include #2379741, and THAT patch should be marked "do-not-test". Otherwise, we can't know if this is working or not :)

Okay, renamed patch to ensure it's tested.

Okay, found that I have to add the renderer.config default parameters in core.services.yml, so luckily it didn't have to do anything with Wim's issue.

Forgot to add parameter 'debug' in core.services.yml which caused many tests to fail. I added debug: false but I'm not sure if this is the best place to put it there.

Reviewed the last interdiff, some nitpicks. But two more important, more fundamental challenges:

1. This needs test coverage.
2. Most importantly: I think the output is actually misleading and I'm not sure if there's a way to fix it… Imagine that you have a render array like this:
   

   $build = [
     '#markup' => 'parent',
     '#cache' => ['cid' => 'parent'],
     'child' => [
       '#markup' => 'child',
       '#cache' => ['cid' => 'child'],
     ],
   ];
   

   When rendered, the child is rendered first, is cached, and "cache miss" debug output is added to its #markup. No problems so far. Now we render the parent. It's also a cache miss. But its output contains the output of the child, which includes the "cache miss" debug output. This is misleading in two ways:
   1) cache hits for the parent imply that caching of the child simply doesn't matter, so the render cache debug output for the child should not be there at all, 2) if it's going to be there, it should reflect reality, and reality is that the child has been cached in the mean time. But now that the parent is cached, it's going to say forever that the child is not cached, even though it is, both individually and part as of its parent.
   The only mitigating factor is that you could decipher this on your own: HTML is hierarchical as well, so we could argue that when looking at the debug output, you should look at whether there are any parent DOM elements that have debug output, and if so, that output is the relevant output. The child's debug output then indicates whether the parent had to rebuild everything, or was able to reuse cached children or not.

Thoughts?

+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -528,4 +546,40 @@ public function getCacheableRenderArray(&$markup, $elements) {
+  /**
+   * @param $elements
+   *   The renderable array that must be wrapped with the cache debug output.
+   * @param $is_cache_hit
+   *   A flag indicating that the cache is hit or miss.
+   * @return array
+   *   The renderable array.
+   */

1. Missing one-line description at the top.
2. Missing typehints.
3. Needs a new line before the @return.

#2379741: Add Renderer::getCacheableRenderArray() to encapsulate which data is needed for caching a render array and have views use it finally landed, so now you can rip that part out of this patch; that'll make this patch easier to review and reroll :)

Yup, i'm going to pick this up really soon.

Crickets ... Anyone up for pushing this along?

This is a reroll of #20. #21 is still not addressed.

I fixed the failing tests and added a new one to check the debug output.

Regarding #21.2: I don't have a good answer on that. The only thing that came to my mind was changing the children to CACHE-HIT: YES by a regex after the parent was retrieved from the cache.

Damn, patch wrong created...

This looks really helpful. I spent some time pondering if this should be merged with twig's debug flag. Because it hard to explain why putting the renderer into debug mode not put twig into debug mode. But I think it is okay to have the two settings because they are different things and having both on at the same time would be very noisy.

+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -756,4 +765,43 @@ protected function ensureMarkupIsSafe(array $elements) {
+    $prefix .= "\n  CACHE-HIT: " . ($is_cache_hit ? 'YES' : 'NO') . "";
...
+      $suffix .= "\nCache tags: [";
...
+      $suffix .= "\nCache keys: [";

Why is CACHE_HIT: indented and the Cache tags: and Cache keys: not. Also why is it in CAPS.

I adjusted the output to be more in line with the twig debug output.

Fixing the test...

#44:
> I spent some time pondering if this should be merged with twig's debug flag. ... But I think it is okay to have the two settings because they are different things and having both on at the same time would be very noisy.

Yes to this.

I also wonder how in the future we relate this to Renderviz ( also by Wim ;-)? First i thought this is renderviz in core but that one dumps the cache metadata (not hit/miss). (Kudos, i really fell in love with it!.) That one also includes Cache Context which this does not (see \Drupal
enderviz\Renderer).

@Wim?

Looks like all feedback has been addressed. And its been 5 years.

++

This looks good to go, can we get a change record please?

> This looks good to go, can we get a change record please?

So this should be NW.

Added change record. Rerolled and fixed test.

1. Use assertStringContainsString(). The code will be easier to understand.

-  preg_match('/CACHE-HIT:\s(No|Yes)/', $markup, $matches);
-  $this->assertEquals('No', $matches[1]);
+  $this->assertStringContainsString('CACHE-HIT: No', $markup);

-  preg_match('/CACHE-HIT:\s(No|Yes)/', $markup, $matches);
-  $this->assertEquals('Yes', $matches[1]);
+  $this->assertStringContainsString('CACHE-HIT: Yes', $markup);

2. Coding standards.

--- a/core/lib/Drupal/Core/Render/Renderer.php
+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -790,7 +790,7 @@ protected function doCallback($callback_type, $callback, array $args) {
     return $this->doTrustedCallback($callback, $args, $message, TrustedCallbackInterface::THROW_EXCEPTION, RenderCallbackInterface::class);
   }
 
-  /*
+  /**
    * Add cache debug information to the render array.

Adresses #58

Thanks @johnwebdev!

If installed Drupal core prior to version 9.1.0 the new option will not be in the services.yml file (copied default.services.yml). Then you will see:

Notice: Undefined index: debug in Drupal\Core\Render\Renderer->doRender() (line 530 of core\lib\Drupal\Core\Render\Renderer.php).

That should be enough:

--- a/core/lib/Drupal/Core/Render/Renderer.php
+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -119,6 +119,9 @@ public function __construct(ControllerResolverInterface $controller_resolver, Th
     $this->elementInfo = $element_info;
     $this->placeholderGenerator = $placeholder_generator;
     $this->renderCache = $render_cache;
+    if (!isset($renderer_config['debug'])) {
+      $renderer_config['debug'] = FALSE;
+    }
     $this->rendererConfig = $renderer_config;

Let's add a cache context to the debug output.

<!-- CACHE CONTEXTS:
   * languages:language_interface
   * theme
   * url.path
   * user.permissions
-->

Adresses #60 and #61

Ah... sorry about that.

[edited]

1. I tested manually. Works correctly. Before RTBC let's refactor the test. It will be more readable if we use the heredoc syntax.

    $expected = <<<EOF


<!-- START RENDERER -->
<!-- CACHE-HIT: No -->
<!-- CACHE TAGS:
   * render_cache_test_tag
   * render_cache_test_tag1
-->
<!-- CACHE CONTEXTS:
   * languages:language_interface
   * theme
-->
<!-- CACHE KEYS:
   * render_cache_test_key
-->
Test 1
<!-- END RENDER -->

EOF;
    $this->assertEquals($expected, $markup);

2. I discovered two "\n" signs at the beginning of the markup. Is that necessary?

Please review.

Back to NW. See #65.

Addressed #65.

Please test and review, thanks!

Debug output with pre-bubbling cache datas and rendering time.

Please test, review and help extening test.

How could this be improved?

> How could this be improved?

It would be great if we didn't have to repeat parameters in sites/development.services.yml which we're not changing, as that violates DRY. I have to do this:

parameters:
  http.response.debug_cacheability_headers: true
  renderer.config:
    required_cache_contexts: ['languages:language_interface', 'theme', 'user.permissions']
    auto_placeholder_conditions:
      max-age: 0
      contexts: ['session', 'user']
      tags: []
    debug: true

when all I really mean is this:

parameters:
  http.response.debug_cacheability_headers: true
  renderer.config:
    # keep everything else the same
    debug: true

But that's out of the scope of this issue, I think. Or not possible at all.

@joachim I think that should be a separate issue, it is surely possible that container parameters could be merged, but it might be tricky when you want to explicitly remove members of an array in an override.

This patch has been super helpful in debugging some caching issues on a complex site, and it still applies back on 8.9.x which I am grateful for. Thanks to everyone who has contributed so far!

+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -781,4 +797,63 @@ protected function doCallback($callback_type, $callback, array $args) {
+    $prefix = "<!-- START RENDERER -->";
...
+    $suffix = "<!-- END RENDER -->";

I think this should be consistent, either RENDER or RENDERER each time.

I have re-rolled it against 9.3.x and updated fix from #80.

Thanks, some coding standards work needed now - these are probably new since the patch was last worked on:

FILE: /var/www/html/core/lib/Drupal/Core/Render/Renderer.php
----------------------------------------------------------------------
FOUND 4 ERRORS AFFECTING 4 LINES
----------------------------------------------------------------------
 813 | ERROR | [x] Parameter comment indentation must be 3 spaces,
     |       |     found 2 spaces
 815 | ERROR | [x] Parameter comment indentation must be 3 spaces,
     |       |     found 2 spaces
 863 | ERROR | [x] Expected 1 blank line after function; 0 found
 864 | ERROR | [x] The closing brace for the class must have an empty
     |       |     line before it

Addressed #82 suggestions, thanks!

* Added native typehints
* Fixes the tests
* RENDER -> RENDERER

Thank you for your work!
I guess that it will be useful to add some ID to <!-- START RENDERER --> and <!-- END RENDERER -->.
To understand where is start and end of each block. And to help searching.
E.g. random int will suit. But better md5(serialize($element)) but it takes more time.

This needs a re-roll.

@Lukas von Blarer
And why?

#85 applies cleanly to 9.4.x and 10.0.x for me.

+++ b/core/assets/scaffold/files/default.services.yml
@@ -132,6 +132,13 @@ parameters:
+    # Not recommended in production environments

We reworded similar sentences in #3166449: Improve wording around twig.cache setting for production environments

I suggest "Enabling render cache debugging is not recommended in production environments."

Otherwise this looks ready to go to me.

Just addressed the change mentioned by @longwave in #91, thanks!

Thanks! As far as I can see there is nothing left to do here.

Just a small error in a comment:

+++ b/core/lib/Drupal/Core/Render/Renderer.php
@@ -276,6 +283,10 @@ protected function doRender(&$elements, $is_root_call = FALSE) {
+        // Add debug output to the renderable array on cache miss.
+        if ($this->rendererConfig['debug'] === TRUE) {
+          $elements = $this->addDebugOutput($elements, TRUE);

Comment is wrong here, since the TRUE being passed in is $is_cache_hit.

Agree with @joachim. Addressed #94

I've applied and tested the patch at on of our projects and I can confirm that it works as expected (and it is super helpful too!).

1. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -772,4 +788,64 @@ protected function doCallback($callback_type, $callback, array $args) {
   +    if (!empty($elements['#markup'])) {
   +      $elements['#markup'] = "$prefix\n" . $elements['#markup'] . "\n$suffix";
   +    }
   

   If there is no $elements['#markup'] then this method is going to have to a load of work for no reason. Should we do an early return if $elements['#markup'] is empty as we have nowhere to attach the markup too... or should we be creating a #markup key/value...

2. +++ b/core/lib/Drupal/Core/Render/Renderer.php
   @@ -276,6 +283,10 @@ protected function doRender(&$elements, $is_root_call = FALSE) {
            if (is_string($elements['#markup'])) {
              $elements['#markup'] = Markup::create($elements['#markup']);
            }
   +        // Add debug output to the renderable array on cache hit.
   +        if ($this->rendererConfig['debug'] === TRUE) {
   +          $elements = $this->addDebugOutput($elements, TRUE);
   +        }
   

   This looks very odd... It looks like we'll be losing the Makrup object-ness of $elements['#markup'] is the debug output is added. That is going to cause problems.

This digits makes me think about precision configuration of PHP - 0.0000000123456789

Great point. What about setting precision to 9 decimal places (nanoseconds) when generating output? I think that we don't need more than that.

I also made the regular expression a bit more specific to make sure that we are actually matching that line.

Thanks 👍 looks ready

This didn't make it into 9.5.0-beta1 and so I don't think we are eligible to add it now. Bumping to 10.1.x which is the next place it can land; the patch still applies.

Please backport 9.5.0.

Committed/pushed to 10.1.x and cherry-picked to 10.0.x, thanks!

I think we might be OK to backport this to 9.5.x during beta - it's a developer-facing feature and doesn't have any API implications, will get another opinion.

Discussed with @xjm and we both think this can be backported. But adding a release note for the changes to default.services.yml

Not sure where we stand on developer-facing features as release highlights, but tagging for 9.5 release highlights in case we want to include it.