FEATURE: Introduce content cache debug mode

Sebobo · Sebobo · commit 910af1060a16 · 2022-03-02T16:30:57.000+01:00
The messages stored with individual content cache tags
take up a lot of unnecessary memory in production
context and not are even used there.

With this change the behaviour can be enabled via
the setting `Neos.Neos.fusion.contentCacheDebugMode`.
diff --git a/Neos.Neos/Classes/Fusion/Cache/ContentCacheFlusher.php b/Neos.Neos/Classes/Fusion/Cache/ContentCacheFlusher.php
@@ -13,6 +13,7 @@
 
 use Neos\ContentRepository\Domain\Model\Workspace;
 use Neos\ContentRepository\Domain\Repository\WorkspaceRepository;
+use Neos\ContentRepository\Exception\NodeTypeNotFoundException;
 use Neos\Flow\Annotations as Flow;
 use Neos\Flow\Log\Utility\LogEnvironment;
 use Neos\Flow\Persistence\PersistenceManagerInterface;
@@ -54,7 +55,7 @@ class ContentCacheFlusher
     protected $systemLogger;
 
     /**
-     * @var array
+     * @var array<string, string>
      */
     protected $tagsToFlush = [];
 
@@ -109,18 +110,22 @@ class ContentCacheFlusher
      */
     protected $securityContext;
 
+    /**
+     * @Flow\InjectConfiguration(path="fusion.contentCacheDebugMode")
+     * @var bool
+     */
+    protected $debugMode;
+
     /**
      * Register a node change for a later cache flush. This method is triggered by a signal sent via ContentRepository's Node
      * model or the Neos Publishing Service.
      *
      * @param NodeInterface $node The node which has changed in some way
-     * @param Workspace $targetWorkspace An optional workspace to flush
-     * @return void
-     * @throws \Neos\ContentRepository\Exception\NodeTypeNotFoundException
+     * @param Workspace|null $targetWorkspace An optional workspace to flush
      */
     public function registerNodeChange(NodeInterface $node, Workspace $targetWorkspace = null): void
     {
-        $this->tagsToFlush[ContentCache::TAG_EVERYTHING] = 'which were tagged with "Everything".';
+        $this->addTagToFlush(ContentCache::TAG_EVERYTHING, 'which were tagged with "Everything".');
 
         if (empty($this->workspacesToFlush[$node->getWorkspace()->getName()])) {
             $this->resolveWorkspaceChain($node->getWorkspace());
@@ -140,10 +145,11 @@ public function registerNodeChange(NodeInterface $node, Workspace $targetWorkspa
         }
     }
 
-    /**
-     * @param NodeInterface $node
-     * @param Workspace $workspace
-     */
+    protected function addTagToFlush(string $tag, string $message = ''): void
+    {
+        $this->tagsToFlush[$tag] = $this->debugMode ? $message : '';
+    }
+
     protected function registerAllTagsToFlushForNodeInWorkspace(NodeInterface $node, Workspace $workspace): void
     {
         $nodeIdentifier = $node->getIdentifier();
@@ -168,32 +174,23 @@ protected function registerAllTagsToFlushForNodeInWorkspace(NodeInterface $node,
                     break;
                 }
                 $tagName = 'DescendantOf_' . $workspaceHash . '_' . $nodeInWorkspace->getIdentifier();
-                $this->tagsToFlush[$tagName] = sprintf('which were tagged with "%s" because node "%s" has changed.', $tagName, $node->getPath());
+                $this->addTagToFlush($tagName, sprintf('which were tagged with "%s" because node "%s" has changed.', $tagName, $node->getPath()));
 
                 $legacyTagName = 'DescendantOf_' . $nodeInWorkspace->getIdentifier();
-                $this->tagsToFlush[$legacyTagName] = sprintf('which were tagged with legacy "%s" because node "%s" has changed.', $legacyTagName, $node->getPath());
+                $this->addTagToFlush($legacyTagName, sprintf('which were tagged with legacy "%s" because node "%s" has changed.', $legacyTagName, $node->getPath()));
             }
         }
     }
 
-    /**
-     * @param Workspace $workspace
-     * @return void
-     */
-    protected function resolveWorkspaceChain(Workspace $workspace)
+    protected function resolveWorkspaceChain(Workspace $workspace): void
     {
         $cachingHelper = $this->getCachingHelper();
 
         $this->workspacesToFlush[$workspace->getName()][$workspace->getName()] = $cachingHelper->renderWorkspaceTagForContextNode($workspace->getName());
         $this->resolveTagsForChildWorkspaces($workspace, $workspace->getName());
     }
 
-    /**
-     * @param Workspace $workspace
-     * @param string $startingPoint
-     * @return void
-     */
-    protected function resolveTagsForChildWorkspaces(Workspace $workspace, string $startingPoint)
+    protected function resolveTagsForChildWorkspaces(Workspace $workspace, string $startingPoint):void
     {
         $cachingHelper = $this->getCachingHelper();
         $this->workspacesToFlush[$startingPoint][$workspace->getName()] = $cachingHelper->renderWorkspaceTagForContextNode($workspace->getName());
@@ -210,54 +207,46 @@ protected function resolveTagsForChildWorkspaces(Workspace $workspace, string $s
      * Pleas use registerNodeChange() if possible. This method is a low-level api. If you do use this method make sure
      * that $cacheIdentifier contains the workspacehash as well as the node identifier: $workspaceHash .'_'. $nodeIdentifier
      * The workspacehash can be received via $this->getCachingHelper()->renderWorkspaceTagForContextNode($workpsacename)
-     *
-     * @param string $cacheIdentifier
      */
-    public function registerChangeOnNodeIdentifier($cacheIdentifier)
+    public function registerChangeOnNodeIdentifier(string $cacheIdentifier): void
     {
-        $this->tagsToFlush[ContentCache::TAG_EVERYTHING] = 'which were tagged with "Everything".';
-        $this->tagsToFlush['Node_' . $cacheIdentifier] = sprintf('which were tagged with "Node_%s" because that identifier has changed.', $cacheIdentifier);
-        $this->tagsToFlush['NodeDynamicTag_' . $cacheIdentifier] = sprintf('which were tagged with "NodeDynamicTag_%s" because that identifier has changed.', $cacheIdentifier);
+        $this->addTagToFlush(ContentCache::TAG_EVERYTHING, 'which were tagged with "Everything".');
+        $this->addTagToFlush('Node_' . $cacheIdentifier, sprintf('which were tagged with "Node_%s" because that identifier has changed.', $cacheIdentifier));
+        $this->addTagToFlush('NodeDynamicTag_' . $cacheIdentifier, sprintf('which were tagged with "NodeDynamicTag_%s" because that identifier has changed.', $cacheIdentifier));
 
         // Note, as we don't have a node here we cannot go up the structure.
         $tagName = 'DescendantOf_' . $cacheIdentifier;
-        $this->tagsToFlush[$tagName] = sprintf('which were tagged with "%s" because node "%s" has changed.', $tagName, $cacheIdentifier);
+        $this->addTagToFlush($tagName, sprintf('which were tagged with "%s" because node "%s" has changed.', $tagName, $cacheIdentifier));
     }
 
     /**
      * This is a low-level api. Please use registerNodeChange() if possible. Otherwise make sure that $nodeTypePrefix
      * is set up correctly and contains the workspacehash wich can be received via
      * $this->getCachingHelper()->renderWorkspaceTagForContextNode($workpsacename)
      *
-     * @param string $nodeTypeName
-     * @param string $referenceNodeIdentifier
-     * @param string $nodeTypePrefix
-     *
-     * @throws \Neos\ContentRepository\Exception\NodeTypeNotFoundException
+     * @throws NodeTypeNotFoundException
      */
-    public function registerChangeOnNodeType($nodeTypeName, $referenceNodeIdentifier = null, $nodeTypePrefix = '')
+    public function registerChangeOnNodeType(string $nodeTypeName, string $referenceNodeIdentifier = null, string $nodeTypePrefix = ''): void
     {
-        $this->tagsToFlush[ContentCache::TAG_EVERYTHING] = 'which were tagged with "Everything".';
+        $this->addTagToFlush(ContentCache::TAG_EVERYTHING, 'which were tagged with "Everything".');
 
         $nodeTypesToFlush = $this->getAllImplementedNodeTypeNames($this->nodeTypeManager->getNodeType($nodeTypeName));
 
-        if (strlen($nodeTypePrefix) > 0) {
+        if ($nodeTypePrefix !== '') {
             $nodeTypePrefix = rtrim($nodeTypePrefix, '_') . '_';
         }
 
         foreach ($nodeTypesToFlush as $nodeTypeNameToFlush) {
-            $this->tagsToFlush['NodeType_' . $nodeTypePrefix . $nodeTypeNameToFlush] = sprintf('which were tagged with "NodeType_%s" because node "%s" has changed and was of type "%s".', $nodeTypeNameToFlush, ($referenceNodeIdentifier ? $referenceNodeIdentifier : ''), $nodeTypeName);
+            $this->addTagToFlush('NodeType_' . $nodeTypePrefix . $nodeTypeNameToFlush, sprintf('which were tagged with "NodeType_%s" because node "%s" has changed and was of type "%s".', $nodeTypeNameToFlush, ($referenceNodeIdentifier ? $referenceNodeIdentifier : ''), $nodeTypeName));
         }
     }
 
     /**
      * Fetches possible usages of the asset and registers nodes that use the asset as changed.
      *
-     * @param AssetInterface $asset
-     * @return void
-     * @throws \Neos\ContentRepository\Exception\NodeTypeNotFoundException
+     * @throws NodeTypeNotFoundException
      */
-    public function registerAssetChange(AssetInterface $asset)
+    public function registerAssetChange(AssetInterface $asset): void
     {
         // In Nodes only assets are referenced, never asset variants directly. When an asset
         // variant is updated, it is passed as $asset, but since it is never "used" by any node
@@ -293,27 +282,30 @@ public function registerAssetChange(AssetInterface $asset)
             $assetIdentifier = $this->persistenceManager->getIdentifierByObject($asset);
             // @see RuntimeContentCache.addTag
             $tagName = 'AssetDynamicTag_' . $workspaceHash . '_' . $assetIdentifier;
-            $this->tagsToFlush[$tagName] = sprintf('which were tagged with "%s" because asset "%s" has changed.', $tagName, $assetIdentifier);
+            $this->addTagToFlush($tagName, sprintf('which were tagged with "%s" because asset "%s" has changed.', $tagName, $assetIdentifier));
         }
     }
 
     /**
      * Flush caches according to the previously registered node changes.
-     *
-     * @return void
      */
-    public function shutdownObject()
+    public function shutdownObject(): void
     {
         if ($this->tagsToFlush !== []) {
-            $affectedEntries = $this->contentCache->flushByTags(array_keys($this->tagsToFlush));
-            $this->systemLogger->debug(sprintf('Content cache: Removed %s entries', $affectedEntries));
+            if ($this->debugMode) {
+                foreach ($this->tagsToFlush as $tag => $logMessage) {
+                    $affectedEntries = $this->contentCache->flushByTag($tag);
+                    if ($affectedEntries > 0) {
+                        $this->systemLogger->debug(sprintf('Content cache: Removed %s entries %s', $affectedEntries, $logMessage));
+                    }
+                }
+            } else {
+                $affectedEntries = $this->contentCache->flushByTags(array_keys($this->tagsToFlush));
+                $this->systemLogger->debug(sprintf('Content cache: Removed %s entries', $affectedEntries));
+            }
         }
     }
 
-    /**
-     * @param AssetUsageInNodeProperties $assetUsage
-     * @return ContentContext
-     */
     protected function getContextForReference(AssetUsageInNodeProperties $assetUsage): ContentContext
     {
         $hash = md5(sprintf('%s-%s', $assetUsage->getWorkspaceName(), json_encode($assetUsage->getDimensionValues())));
@@ -330,10 +322,9 @@ protected function getContextForReference(AssetUsageInNodeProperties $assetUsage
     }
 
     /**
-     * @param NodeType $nodeType
      * @return array<string>
      */
-    protected function getAllImplementedNodeTypeNames(NodeType $nodeType)
+    protected function getAllImplementedNodeTypeNames(NodeType $nodeType): array
     {
         $self = $this;
         $types = array_reduce($nodeType->getDeclaredSuperTypes(), function (array $types, NodeType $superType) use ($self) {
@@ -344,9 +335,6 @@ protected function getAllImplementedNodeTypeNames(NodeType $nodeType)
         return $types;
     }
 
-    /**
-     * @return CachingHelper
-     */
     protected function getCachingHelper(): CachingHelper
     {
         if (!$this->cachingHelper instanceof CachingHelper) {
diff --git a/Neos.Neos/Configuration/Settings.yaml b/Neos.Neos/Configuration/Settings.yaml
@@ -21,6 +21,11 @@ Neos:
       # - in Production context
       enableObjectTreeCache: false
 
+      # If set to true, content cache flushes will be done on a per-tag basis and generate additional log output
+      # which allows understanding why flushed entries were flushed. This is useful for debugging but will
+      # hurt performance and should not be used in production.
+      contentCacheDebugMode: false
+
       # Packages can now register with this setting to get their Fusion in the path:
       # resources://MyVendor.MyPackageKey/Private/Fusion/Root.fusion
       # included automatically.
diff --git a/Neos.Neos/Tests/Unit/Fusion/Cache/ContentCacheFlusherTest.php b/Neos.Neos/Tests/Unit/Fusion/Cache/ContentCacheFlusherTest.php
@@ -16,7 +16,6 @@
 use Neos\ContentRepository\Domain\Model\Workspace;
 use Neos\Flow\Tests\UnitTestCase;
 use Neos\Neos\Fusion\Cache\ContentCacheFlusher;
-use Neos\Neos\Fusion\Helper\CachingHelper;
 
 /**
  * Tests the CachingHelper
@@ -44,6 +43,7 @@ public function theWorkspaceChainWillOnlyEvaluatedIfNeeded()
         $nodeMock = $this->getMockBuilder(NodeInterface::class)->disableOriginalConstructor()->getMock();
         $nodeMock->expects(self::any())->method('getWorkspace')->willReturn($workspace);
         $nodeMock->expects(self::any())->method('getNodeType')->willReturn($nodeType);
+        $nodeMock->expects(self::any())->method('getIdentifier')->willReturn('some-node-identifier');
 
         $contentCacheFlusher->registerNodeChange($nodeMock);
     }
