FEATURE: Show render metrics for cached elements

Classes/Aspect/CollectDebugInformationAspect.php

@@ -137,8 +137,8 @@ public function addDebugValues(JoinPointInterface $joinPoint): string
      */
     public function startSqlLogging(\Neos\Flow\AOP\JoinPointInterface $joinPoint): void
     {
-         $this->sqlLoggingStack = new DebugStack();
-         $this->entityManager->getConfiguration()->setSQLLogger($this->sqlLoggingStack);
+        $this->sqlLoggingStack = new DebugStack();
+        $this->entityManager->getConfiguration()->setSQLLogger($this->sqlLoggingStack);
     }
 
     /**

Classes/Aspect/ContentCacheSegmentAspect.php

@@ -20,6 +20,7 @@
 use Neos\Fusion\Core\Cache\ContentCache;
 use Neos\Fusion\FusionObjects\AbstractFusionObject;
 use Neos\Utility\ObjectAccess;
+use t3n\Neos\Debug\Service\RenderTimer;
 
 /**
  * @Flow\Scope("singleton")
@@ -46,6 +47,13 @@ class ContentCacheSegmentAspect
      */
     protected $interceptedFusionObject;
 
+    /**
+     * @Flow\Inject
+     *
+     * @var RenderTimer
+     */
+    protected $renderTimer;
+
     public function injectContentCache(ContentCache $contentCache): void
     {
         $randomCacheMarker = ObjectAccess::getProperty($contentCache, 'randomCacheMarker', true);
@@ -65,10 +73,13 @@ public function debuggingActive(): void
     public function wrapCachedSegment(JoinPointInterface $joinPoint): string
     {
         $segment = $joinPoint->getAdviceChain()->proceed($joinPoint);
+        $fusionPath = $joinPoint->getMethodArgument('fusionPath');
+        $renderTime = $this->renderTimer->stop($fusionPath);
 
         return $this->renderCacheInfoIntoSegment($segment, [
             'mode' => static::MODE_CACHED,
-            'fusionPath' => $joinPoint->getMethodArgument('fusionPath'),
+            'fusionPath' => $fusionPath,
+            'renderMetrics' => $renderTime,
             'entryIdentifier' => $this->interceptedCacheEntryValues,
             'entryTags' => $joinPoint->getMethodArgument('tags'),
             'lifetime' => $joinPoint->getMethodArgument('lifetime')

Classes/Aspect/RuntimeTracingAspect.php

@@ -0,0 +1,57 @@
+<?php
+
+declare(strict_types=1);
+
+namespace t3n\Neos\Debug\Aspect;
+
+/**
+ * This file is part of the t3n.Neos.Debugger package.
+ *
+ * (c) 2019 yeebase media GmbH
+ *
+ * This package is Open Source Software. For the full copyright and license
+ * information, please view the LICENSE file which was distributed with this
+ * source code.
+ */
+
+use Neos\Flow\Annotations as Flow;
+use Neos\Flow\Aop\JoinPointInterface;
+use t3n\Neos\Debug\Service\RenderTimer;
+
+/**
+ * @Flow\Aspect
+ * @Flow\Scope("singleton")
+ */
+class RuntimeTracingAspect
+{
+    /**
+     * @Flow\Inject
+     *
+     * @var RenderTimer
+     */
+    protected $renderTimer;
+
+    /**
+     * @Flow\Pointcut("setting(t3n.Neos.Debug.enabled)")
+     */
+    public function debuggingActive(): void
+    {
+    }
+
+    /**
+     * @Flow\Before("method(Neos\Fusion\Core\Cache\RuntimeContentCache->enter()) && t3n\Neos\Debug\Aspect\RuntimeTracingAspect->debuggingActive")
+     */
+    public function onEnter(JoinPointInterface $joinPoint): void
+    {
+        $configuration = $joinPoint->getMethodArgument('configuration');
+        $fusionPath = $joinPoint->getMethodArgument('fusionPath');
+
+        $cacheMode = $configuration['mode'] ?? null;
+
+        if (! $cacheMode) {
+            return;
+        }
+
+        $this->renderTimer->start($fusionPath);
+    }
+}

Classes/Service/RenderTimer.php

@@ -0,0 +1,80 @@
+<?php
+
+declare(strict_types=1);
+
+namespace t3n\Neos\Debug\Service;
+
+/**
+ * This file is part of the t3n.Neos.Debugger package.
+ *
+ * (c) 2019 yeebase media GmbH
+ *
+ * This package is Open Source Software. For the full copyright and license
+ * information, please view the LICENSE file which was distributed with this
+ * source code.
+ */
+
+use Doctrine\ORM\EntityManagerInterface;
+use Neos\Flow\Annotations as Flow;
+use t3n\Neos\Debug\Logging\DebugStack;
+
+/**
+ * @Flow\Scope("singleton")
+ */
+class RenderTimer
+{
+    /**
+     * @Flow\Inject()
+     *
+     * @var EntityManagerInterface
+     */
+    protected $entityManager;
+
+    /**
+     * @var mixed[]
+     */
+    protected $renderMetrics = [];
+
+    /**
+     * Starts a render timer for a certain fusion path
+     */
+    public function start(string $fusionPath): void
+    {
+        $sqlLoggingStack = $this->entityManager->getConfiguration()->getSQLLogger();
+        $queryCount = $sqlLoggingStack instanceof DebugStack ? $sqlLoggingStack->queryCount : 0;
+
+        $this->renderMetrics[$fusionPath] = [
+            'startRenderAt' => $this->ts(),
+            'sqlQueryCount' => $queryCount,
+        ];
+    }
+
+    /**
+     * Return current microtime in ms
+     */
+    private function ts(): float
+    {
+        return microtime(true) * 1000;
+    }
+
+    /**
+     * Stops the timer and returns the computed values
+     *
+     * @return mixed[]|null
+     */
+    public function stop(string $fusionPath): ?array
+    {
+        if (! array_key_exists($fusionPath, $this->renderMetrics)) {
+            return null;
+        }
+
+        $metrics = $this->renderMetrics[$fusionPath];
+        $sqlLoggingStack = $this->entityManager->getConfiguration()->getSQLLogger();
+        $queryCount = $sqlLoggingStack instanceof DebugStack ? $sqlLoggingStack->queryCount : 0;
+
+        return [
+            'renderTime' => round($this->ts() - $metrics['startRenderAt'], 2) . ' ms',
+            'sqlQueryCount' => $queryCount - $metrics['sqlQueryCount'],
+        ];
+    }
+}