FEATURE: add plumber performance profiling

Classes/NodeRendering/NodeRenderer.php

@@ -18,6 +18,8 @@
 use Flowpack\DecoupledContentStore\NodeRendering\ProcessEvents\ExitEvent;
 use Flowpack\DecoupledContentStore\NodeRendering\ProcessEvents\QueueEmptyEvent;
 use Flowpack\DecoupledContentStore\NodeRendering\Render\DocumentRenderer;
+use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerInterface;
+use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerProvider;
 use Flowpack\DecoupledContentStore\PrepareContentRelease\Infrastructure\RedisContentReleaseService;
 use Neos\ContentRepository\Domain\Model\NodeInterface;
 use Neos\ContentRepository\Domain\Service\ContextFactoryInterface;
@@ -55,6 +57,18 @@ class NodeRenderer
     protected const RESTART_AFTER_RENDER_COUNT = 20;
     protected const CHECK_FOR_CONCURRENT_RELEASES_RENDER_COUNT = 5;
 
+    /**
+     * Name of the span around every document rendering. It is the same for all documents on purpose, so that a
+     * profiler can sum it up into a single "time spent rendering documents" figure.
+     */
+    public const SPAN_RENDER_DOCUMENT = 'Content Release: Render Document';
+
+    /**
+     * Prefix of the per-document span. Distinct name per document, which is what makes a timeline view and
+     * "group by span name" useful.
+     */
+    public const SPAN_DOCUMENT_PREFIX = 'Content Release Document: ';
+
     /**
      * @Flow\Inject
      * @var DocumentRenderer
@@ -133,13 +147,21 @@ class NodeRenderer
      */
     protected $nodeRenderingExtensionManager;
 
+    #[Flow\Inject]
+    protected RenderTracerProvider $renderTracerProvider;
+
     public function render(
         ContentReleaseIdentifier $contentReleaseIdentifier,
         ContentReleaseLogger $contentReleaseLogger,
         RendererIdentifier $rendererIdentifier,
     ) {
         $contentReleaseLogger = $contentReleaseLogger->withRenderer($rendererIdentifier);
 
+        $this->renderTracerProvider->getTracer()->describeRun([
+            RenderTracerInterface::META_CONTENT_RELEASE => $contentReleaseIdentifier->getIdentifier(),
+            RenderTracerInterface::META_RENDERER => $rendererIdentifier->string(),
+        ]);
+
         $i = 0;
         while (true) {
             $renderStatus = $this->redisContentReleaseService
@@ -268,11 +290,25 @@ protected function renderDocumentNodeVariant(
                     'arguments' => $enumeratedNode->getArguments(),
                 ]);
 
-                $this->nodeRenderingExtensionManager->renderDocumentNodeVariant(
-                    $node,
-                    $enumeratedNode,
-                    $contentReleaseLogger,
-                );
+                $tracer = $this->renderTracerProvider->getTracer();
+                $spanParams = [
+                    'node' => $node->getContextPath(),
+                    'site' => $enumeratedNode->getSiteNodeNameFromContextPath(),
+                    'dimensions' => $enumeratedNode->getDimensionsFromContextPath(),
+                    'arguments' => $enumeratedNode->getArguments(),
+                ];
+                $tracer->openSpan(self::SPAN_RENDER_DOCUMENT, $spanParams);
+                $tracer->openSpan(self::SPAN_DOCUMENT_PREFIX . $node->getContextPath(), $spanParams);
+                try {
+                    $this->nodeRenderingExtensionManager->renderDocumentNodeVariant(
+                        $node,
+                        $enumeratedNode,
+                        $contentReleaseLogger,
+                    );
+                } finally {
+                    $tracer->closeSpan();
+                    $tracer->closeSpan();
+                }
             }
 
             // NOTE: we do not abort rendering directly, when we encounter any error, but we try to render

Classes/NodeRendering/Tracing/NullTracer.php

@@ -0,0 +1,27 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+/**
+ * Used when no performanceTracer is configured, so that the rendering can call the tracer unconditionally.
+ */
+final class NullTracer implements RenderTracerInterface
+{
+    public function openSpan(string $name, array $params = []): void
+    {
+    }
+
+    public function closeSpan(): void
+    {
+    }
+
+    public function mark(string $name, array $params = []): void
+    {
+    }
+
+    public function describeRun(array $meta): void
+    {
+    }
+}

Classes/NodeRendering/Tracing/PlumberTracer.php

@@ -0,0 +1,85 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+use Sandstorm\Plumber\Core\Domain\Model\EmptyProfilingRun;
+
+/**
+ * Records the rendering spans into the Plumber profiling run of the current render worker, so they show up in
+ * /plumber next to the Fusion and database timers of the very same process.
+ *
+ * Spans are written when they close, not when they open: their duration is only known then, and
+ * $minimumDurationMs drops the fast ones. The consequence is that spans end up as siblings of each other rather
+ * than nested - ProfilingRun::manualTimer() appends a start and a stop event in one go and cannot express a
+ * parent. The nesting is still recoverable from the timestamps, which is what the timeline exports use.
+ *
+ * @see RenderTracerInterface for the reason this lives outside Sandstorm.Plumber
+ */
+final class PlumberTracer implements RenderTracerInterface
+{
+    /**
+     * Open spans, innermost last. Each entry is [name, params, startTimestamp].
+     *
+     * @var list<array{0: string, 1: array<string, mixed>, 2: float}>
+     */
+    private array $openSpans = [];
+
+    public function __construct(
+        private readonly EmptyProfilingRun $profilingRun,
+        private readonly float $minimumDurationMs,
+    ) {
+    }
+
+    public function openSpan(string $name, array $params = []): void
+    {
+        $this->openSpans[] = [$name, $params, microtime(true)];
+    }
+
+    public function closeSpan(): void
+    {
+        $span = array_pop($this->openSpans);
+        if ($span === null) {
+            throw new \RuntimeException('closeSpan() was called without a matching openSpan()', 1756200002);
+        }
+
+        [$name, $params, $startTimestamp] = $span;
+        $stopTimestamp = microtime(true);
+        if (($stopTimestamp - $startTimestamp) * 1000 < $this->minimumDurationMs) {
+            return;
+        }
+
+        // A worker restarts every RESTART_AFTER_RENDER_COUNT documents, so a full release produces ~1800
+        // profiles. With a threshold set, the factory armed the run to be thrown away unless something crossed
+        // it - this is that something, so the profile is worth writing.
+        $this->profilingRun->markAsRelevant();
+        $this->profilingRun->manualTimer($name, $params, $startTimestamp, $stopTimestamp);
+    }
+
+    public function mark(string $name, array $params = []): void
+    {
+        $this->profilingRun->timestamp($name, $params);
+    }
+
+    public function describeRun(array $meta): void
+    {
+        foreach ($meta as $key => $value) {
+            $this->profilingRun->setOption($key, $value);
+        }
+
+        $contentReleaseIdentifier = $meta[RenderTracerInterface::META_CONTENT_RELEASE] ?? null;
+        if ($contentReleaseIdentifier === null) {
+            return;
+        }
+
+        // The tag is what ties the profiles of all render workers of one release together; every worker restarts
+        // after RESTART_AFTER_RENDER_COUNT documents and writes its own profile.
+        $tag = 'contentRelease:' . $contentReleaseIdentifier;
+        $tags = $this->profilingRun->getTags();
+        if (!in_array($tag, $tags, true)) {
+            $tags[] = $tag;
+            $this->profilingRun->setTags($tags);
+        }
+    }
+}

Classes/NodeRendering/Tracing/PlumberTracerFactory.php

@@ -0,0 +1,40 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+use Sandstorm\Plumber\Core\Profiler;
+
+/**
+ * Options:
+ *   minimumDocumentDurationMs - documents faster than this are not recorded at all. 0 records everything.
+ */
+final class PlumberTracerFactory implements RenderTracerFactoryInterface
+{
+    public function build(array $options): RenderTracerInterface
+    {
+        if (!class_exists(Profiler::class)) {
+            throw new \RuntimeException(
+                'The configured performanceTracer needs sandstorm/plumber, which is not installed. Either run'
+                . ' "composer require --dev sandstorm/plumber" or comment the performanceTracer setting out again.',
+                1756200003,
+            );
+        }
+
+        // startIfNotRunning() instead of getRun(): Sandstorm.Plumber is normally switched off, so that a
+        // backend click does not end up in the profile list next to the content release. Starting the run
+        // here means the process which renders documents is the only one which produces a profile at all.
+        $profilingRun = Profiler::getInstance()->startIfNotRunning();
+
+        $minimumDocumentDurationMs = (float)($options['minimumDocumentDurationMs'] ?? 0);
+        if ($minimumDocumentDurationMs > 0) {
+            // A render worker restarts every twenty documents and each restart writes a profile, so a full
+            // release leaves ~1800 of them behind and /plumber cannot open that many. With a threshold set,
+            // only the batches in which a document actually crossed it are kept.
+            $profilingRun->discardUnlessMarkedRelevant();
+        }
+
+        return new PlumberTracer($profilingRun, $minimumDocumentDurationMs);
+    }
+}

Classes/NodeRendering/Tracing/RenderTracerFactoryInterface.php

@@ -0,0 +1,19 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+/**
+ * Builds the tracer configured at Flowpack.DecoupledContentStore.nodeRendering.performanceTracer.
+ *
+ * Neos 9 passes a ContentRepositoryId to its equivalent; there is no such thing here, so only the free-form
+ * options from the settings are handed over.
+ */
+interface RenderTracerFactoryInterface
+{
+    /**
+     * @param array<string, mixed> $options
+     */
+    public function build(array $options): RenderTracerInterface;
+}

Classes/NodeRendering/Tracing/RenderTracerInterface.php

@@ -0,0 +1,51 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+/**
+ * Collects timing information about the rendering of a content release.
+ *
+ * The three span methods mirror Neos 9's
+ * \Neos\ContentRepository\Core\Infrastructure\PerformanceTracing\PerformanceTracerInterface method for method, so
+ * that a Neos 9 upgrade can drop this interface and use theirs. {@see describeRun()} is the one addition: a render
+ * worker is a whole process with a content release and a renderer id attached to it, and that metadata belongs to
+ * no single span.
+ *
+ * Implementations are instantiated through {@see RenderTracerFactoryInterface} and configured at
+ * Flowpack.DecoupledContentStore.nodeRendering.performanceTracer. When nothing is configured, {@see NullTracer}
+ * is used, so call sites never need a null check.
+ */
+interface RenderTracerInterface
+{
+    /**
+     * Key of the content release identifier within the {@see describeRun()} metadata. Tracers which turn the
+     * metadata into a display label can use it as it is.
+     */
+    public const META_CONTENT_RELEASE = 'Content Release';
+
+    /**
+     * Key of the renderer id within the {@see describeRun()} metadata.
+     */
+    public const META_RENDERER = 'Renderer';
+
+    /**
+     * @param array<string, mixed> $params
+     */
+    public function openSpan(string $name, array $params = []): void;
+
+    public function closeSpan(): void;
+
+    /**
+     * @param array<string, mixed> $params
+     */
+    public function mark(string $name, array $params = []): void;
+
+    /**
+     * Metadata describing the whole worker process, e.g. the content release it renders for.
+     *
+     * @param array<string, string> $meta
+     */
+    public function describeRun(array $meta): void;
+}

Classes/NodeRendering/Tracing/RenderTracerProvider.php

@@ -0,0 +1,56 @@
+<?php
+
+declare(strict_types=1);
+
+namespace Flowpack\DecoupledContentStore\NodeRendering\Tracing;
+
+use Neos\Flow\Annotations as Flow;
+
+/**
+ * Builds the configured tracer once per process.
+ *
+ * Absence of the setting is the "off" state - there is no boolean to flip, the configuration simply names a
+ * factory or it does not. This follows the performanceTracer slot of the Neos 9 ContentRepositoryRegistry.
+ */
+#[Flow\Scope('singleton')]
+class RenderTracerProvider
+{
+    /**
+     * @var array{factoryObjectName: ?string, options: ?array{minimumDocumentDurationMs: int}}|null
+     */
+    #[Flow\InjectConfiguration('nodeRendering.performanceTracer')]
+    protected ?array $configuration = null;
+
+    protected ?RenderTracerInterface $tracer = null;
+
+    public function getTracer(): RenderTracerInterface
+    {
+        if ($this->tracer === null) {
+            $this->tracer = $this->buildTracer();
+        }
+
+        return $this->tracer;
+    }
+
+    private function buildTracer(): RenderTracerInterface
+    {
+        $factoryObjectName = $this->configuration['factoryObjectName'] ?? null;
+        if (!is_string($factoryObjectName) || $factoryObjectName === '') {
+            return new NullTracer();
+        }
+
+        $factory = new $factoryObjectName();
+        if (!$factory instanceof RenderTracerFactoryInterface) {
+            throw new \RuntimeException(
+                sprintf(
+                    'The configured performanceTracer factory %s does not implement %s',
+                    $factoryObjectName,
+                    RenderTracerFactoryInterface::class,
+                ),
+                1756200001,
+            );
+        }
+
+        return $factory->build($this->configuration['options'] ?? []);
+    }
+}

Configuration/Settings.yaml

@@ -62,6 +62,16 @@ Flowpack:
       # Recurse to child nodes of hidden nodes
       recurseHiddenContent: false
 
+      # PERFORMANCE TRACING (Local Debugging)
+      # Records how long every single document takes to render, so you can see which page is slow.
+      # Needs sandstorm/plumber (see the composer "suggest" section and the README).
+      # To enable tracing of the rendering, comment-in the following lines:
+      # performanceTracer:
+      #   factoryObjectName: Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory
+      #   options:
+      #     # how long must a document take to be recorded? if 0, everything is recorded.
+      #     minimumDocumentDurationMs: 0
+
 
 
     extensions: