From 587e34c73eb2efbbc7d9511f1734bf51543c7648 Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Wed, 26 Aug 2026 12:32:55 +0200 Subject: [PATCH 1/6] add plumber --- Classes/NodeRendering/NodeRenderer.php | 46 +++++- Classes/NodeRendering/Tracing/NullTracer.php | 27 ++++ .../NodeRendering/Tracing/PlumberTracer.php | 81 +++++++++++ .../Tracing/PlumberTracerFactory.php | 30 ++++ .../Tracing/RenderTracerFactoryInterface.php | 19 +++ .../Tracing/RenderTracerInterface.php | 51 +++++++ .../Tracing/RenderTracerProvider.php | 53 +++++++ Configuration/Settings.yaml | 10 ++ README.md | 36 +++++ .../Tracing/PlumberTracerTest.php | 132 ++++++++++++++++++ composer.json | 3 + 11 files changed, 483 insertions(+), 5 deletions(-) create mode 100644 Classes/NodeRendering/Tracing/NullTracer.php create mode 100644 Classes/NodeRendering/Tracing/PlumberTracer.php create mode 100644 Classes/NodeRendering/Tracing/PlumberTracerFactory.php create mode 100644 Classes/NodeRendering/Tracing/RenderTracerFactoryInterface.php create mode 100644 Classes/NodeRendering/Tracing/RenderTracerInterface.php create mode 100644 Classes/NodeRendering/Tracing/RenderTracerProvider.php create mode 100644 Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php diff --git a/Classes/NodeRendering/NodeRenderer.php b/Classes/NodeRendering/NodeRenderer.php index d9f1447..9d851ca 100644 --- a/Classes/NodeRendering/NodeRenderer.php +++ b/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,6 +147,9 @@ class NodeRenderer */ protected $nodeRenderingExtensionManager; + #[Flow\Inject] + protected RenderTracerProvider $renderTracerProvider; + public function render( ContentReleaseIdentifier $contentReleaseIdentifier, ContentReleaseLogger $contentReleaseLogger, @@ -140,6 +157,11 @@ public function render( ) { $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 diff --git a/Classes/NodeRendering/Tracing/NullTracer.php b/Classes/NodeRendering/Tracing/NullTracer.php new file mode 100644 index 0000000..7674491 --- /dev/null +++ b/Classes/NodeRendering/Tracing/NullTracer.php @@ -0,0 +1,27 @@ +, 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; + } + + $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); + } + } +} diff --git a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php new file mode 100644 index 0000000..af21ff1 --- /dev/null +++ b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php @@ -0,0 +1,30 @@ +getRun(), + (float)($options['minimumDocumentDurationMs'] ?? 0), + ); + } +} diff --git a/Classes/NodeRendering/Tracing/RenderTracerFactoryInterface.php b/Classes/NodeRendering/Tracing/RenderTracerFactoryInterface.php new file mode 100644 index 0000000..14fcfa9 --- /dev/null +++ b/Classes/NodeRendering/Tracing/RenderTracerFactoryInterface.php @@ -0,0 +1,19 @@ + $options + */ + public function build(array $options): RenderTracerInterface; +} diff --git a/Classes/NodeRendering/Tracing/RenderTracerInterface.php b/Classes/NodeRendering/Tracing/RenderTracerInterface.php new file mode 100644 index 0000000..e1f26e9 --- /dev/null +++ b/Classes/NodeRendering/Tracing/RenderTracerInterface.php @@ -0,0 +1,51 @@ + $params + */ + public function openSpan(string $name, array $params = []): void; + + public function closeSpan(): void; + + /** + * @param array $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 $meta + */ + public function describeRun(array $meta): void; +} diff --git a/Classes/NodeRendering/Tracing/RenderTracerProvider.php b/Classes/NodeRendering/Tracing/RenderTracerProvider.php new file mode 100644 index 0000000..2cd004a --- /dev/null +++ b/Classes/NodeRendering/Tracing/RenderTracerProvider.php @@ -0,0 +1,53 @@ +tracer === null) { + $this->tracer = $this->buildTracer(); + } + + return $this->tracer; + } + + protected 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'] ?? []); + } +} diff --git a/Configuration/Settings.yaml b/Configuration/Settings.yaml index d9ea77b..2efb6d2 100644 --- a/Configuration/Settings.yaml +++ b/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: diff --git a/README.md b/README.md index 4e32616..2144571 100644 --- a/README.md +++ b/README.md @@ -729,6 +729,42 @@ so out loud. If you hit it on an older version, flush the affected documents fro The orchestrator's exit codes: `1` release already completed, `2` empty enumeration, `3` retry limit reached, `4` rendering errors. +#### Finding out which document is slow + +The rendering has a tracer slot at +`Flowpack.DecoupledContentStore.nodeRendering.performanceTracer`. There is no on/off flag: the setting either +names a factory or it is absent, and absent means nothing is recorded. Comment it in: + +```yaml +Flowpack: + DecoupledContentStore: + nodeRendering: + performanceTracer: + factoryObjectName: Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory + options: + # how long must a document take to be recorded? if 0, everything is recorded. + minimumDocumentDurationMs: 0 +``` + +The shipped implementation needs [sandstorm/plumber](https://github.com/sandstorm/Plumber) +(`composer require --dev sandstorm/plumber`), which must have profiling switched on itself +(`Sandstorm.Plumber.enabled: true`). The factory throws if the package is missing - the setting is only ever +reachable when somebody configured it on purpose, so it fails loudly rather than silently doing nothing. + +Two spans are recorded per document: `Content Release: Render Document`, same name for every document so a +profiler can sum it into one figure, and `Content Release Document: `, one distinct name per page. + +What the resulting profiles look like: + +* **One profile per render worker run, not per release, and not per document.** A worker restarts itself after 20 + documents (`RESTART_AFTER_RENDER_COUNT`), and every restart writes its own profile. A release rendered by four + workers therefore leaves `ceil(documents / 20)` profiles behind. +* All of them carry the tag `contentRelease:` and the run options `Content Release` and `Renderer`, + which is how you collect the profiles belonging to one release. + +To write your own tracer - e.g. one that just appends `durationurl` lines and needs no Plumber at all - +implement `RenderTracerInterface` plus `RenderTracerFactoryInterface` and point `factoryObjectName` at it. + ### Testing the Rendering The behavioral tests need the `neos/behat` package (`composer require --dev neos/behat`), which brings Behat itself diff --git a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php new file mode 100644 index 0000000..8764598 --- /dev/null +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -0,0 +1,132 @@ +buildProvider(null)->getTracer()); + self::assertInstanceOf(NullTracer::class, $this->buildProvider([])->getTracer()); + } + + public function testAConfiguredFactoryIsUsed(): void + { + $provider = $this->buildProvider([ + 'factoryObjectName' => \Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory::class, + 'options' => ['minimumDocumentDurationMs' => 0], + ]); + + self::assertInstanceOf(PlumberTracer::class, $provider->getTracer()); + } + + public function testAFactoryWhichDoesNotImplementTheInterfaceIsRejected(): void + { + $this->expectException(\RuntimeException::class); + $this->buildProvider(['factoryObjectName' => \stdClass::class])->getTracer(); + } + + public function testSpansAreRecordedWithTheirNameAndParams(): void + { + $run = new ProfilingRun(); + $run->start(); + $tracer = new PlumberTracer($run, 0.0); + + $tracer->openSpan('Content Release: Render Document', ['site' => 'louis']); + $tracer->openSpan('Content Release Document: /sites/louis@live', ['site' => 'louis']); + $tracer->closeSpan(); + $tracer->closeSpan(); + + $timers = $this->timersByName($run); + self::assertArrayHasKey('Content Release: Render Document', $timers); + self::assertArrayHasKey('Content Release Document: /sites/louis@live', $timers); + self::assertSame(['site' => 'louis'], $timers['Content Release: Render Document']['data']); + } + + public function testADocumentBelowTheThresholdIsNotRecorded(): void + { + $run = new ProfilingRun(); + $run->start(); + $tracer = new PlumberTracer($run, 50.0); + + $tracer->openSpan('fast'); + $tracer->closeSpan(); + + $tracer->openSpan('slow'); + usleep(60000); + $tracer->closeSpan(); + + $timers = $this->timersByName($run); + self::assertArrayNotHasKey('fast', $timers); + self::assertArrayHasKey('slow', $timers); + } + + public function testClosingMoreSpansThanWereOpenedIsAnError(): void + { + $this->expectException(\RuntimeException::class); + (new PlumberTracer(new ProfilingRun(), 0.0))->closeSpan(); + } + + public function testTheRunIsTaggedWithTheContentReleaseItRendersFor(): void + { + $run = new ProfilingRun(); + $run->start(); + $tracer = new PlumberTracer($run, 0.0); + + $tracer->describeRun([ + RenderTracerInterface::META_CONTENT_RELEASE => '1756123456', + RenderTracerInterface::META_RENDERER => 'htmlViaFusion', + ]); + + self::assertSame(['contentRelease:1756123456'], $run->getTags()); + self::assertSame( + ['Content Release' => '1756123456', 'Renderer' => 'htmlViaFusion'], + $run->getOptions(), + ); + } + + private function buildProvider(?array $configuration): RenderTracerProvider + { + $provider = new RenderTracerProvider(); + $reflection = new \ReflectionProperty(RenderTracerProvider::class, 'configuration'); + $reflection->setAccessible(true); + $reflection->setValue($provider, $configuration); + + return $provider; + } + + /** + * @return array + */ + private function timersByName(ProfilingRun $run): array + { + $timers = []; + foreach ($run->getTimersAsDuration() as $timer) { + $timers[$timer['name']] = $timer; + } + unset($timers['Profiling Run']); + + return $timers; + } +} diff --git a/composer.json b/composer.json index 82b3768..ce7c012 100644 --- a/composer.json +++ b/composer.json @@ -9,6 +9,9 @@ "albertofem/rsync-lib": "~1.0", "flowpack/prunner": "*" }, + "suggest": { + "sandstorm/plumber": "Profiles the rendering of a content release, so you can see which document is slow. Comment in Flowpack.DecoupledContentStore.nodeRendering.performanceTracer to use it." + }, "require-dev": { "phpstan/phpstan": "^2.2", "phpstan/phpstan-phpunit": "^2.0", From 61e3492f00be5bda530eb9f6f9eba872b6eb18e0 Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Thu, 27 Aug 2026 10:53:32 +0200 Subject: [PATCH 2/6] allow profiling of a part of a process --- .../Tracing/PlumberTracerFactory.php | 5 ++- README.md | 14 ++++++-- .../Tracing/PlumberTracerTest.php | 32 +++++++++++++++++++ 3 files changed, 47 insertions(+), 4 deletions(-) diff --git a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php index af21ff1..b5ebd31 100644 --- a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php +++ b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php @@ -22,8 +22,11 @@ public function build(array $options): RenderTracerInterface ); } + // 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. return new PlumberTracer( - Profiler::getInstance()->getRun(), + Profiler::getInstance()->startIfNotRunning(), (float)($options['minimumDocumentDurationMs'] ?? 0), ); } diff --git a/README.md b/README.md index 2144571..8229a88 100644 --- a/README.md +++ b/README.md @@ -747,9 +747,14 @@ Flowpack: ``` The shipped implementation needs [sandstorm/plumber](https://github.com/sandstorm/Plumber) -(`composer require --dev sandstorm/plumber`), which must have profiling switched on itself -(`Sandstorm.Plumber.enabled: true`). The factory throws if the package is missing - the setting is only ever -reachable when somebody configured it on purpose, so it fails loudly rather than silently doing nothing. +(`composer require --dev sandstorm/plumber`) to be installed, but **not** to be switched on. Leave +`Sandstorm.Plumber.enabled` at `false`: the factory calls `Profiler::startIfNotRunning()`, so a profiling run +begins in the process which renders documents and nowhere else. That keeps the profile list free of the runs +every backend click would otherwise produce, which is what makes the list usable - each entry is one render +worker of one content release. `PLUMBER_ENABLED=0` still switches everything off, including this. + +The factory throws if the package is missing - the setting is only ever reachable when somebody configured it on +purpose, so it fails loudly rather than silently doing nothing. Two spans are recorded per document: `Content Release: Render Document`, same name for every document so a profiler can sum it into one figure, and `Content Release Document: `, one distinct name per page. @@ -761,6 +766,9 @@ What the resulting profiles look like: workers therefore leaves `ceil(documents / 20)` profiles behind. * All of them carry the tag `contentRelease:` and the run options `Content Release` and `Renderer`, which is how you collect the profiles belonging to one release. +* The profile starts with the first document, not with the process, because that is where the run is started. + Bootstrap and command startup are therefore not in it. Use `PLUMBER_ENABLED=1` on a single + `./flow nodeRendering:renderWorker` call if you need those too. To write your own tracer - e.g. one that just appends `durationurl` lines and needs no Plumber at all - implement `RenderTracerInterface` plus `RenderTracerFactoryInterface` and point `factoryObjectName` at it. diff --git a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php index 8764598..7a386ae 100644 --- a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -8,8 +8,10 @@ use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracer; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerInterface; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerProvider; +use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory; use Neos\Flow\Tests\UnitTestCase; use Sandstorm\Plumber\Core\Domain\Model\ProfilingRun; +use Sandstorm\Plumber\Core\Profiler; /** * Tests the tracer slot of the rendering against a real Plumber ProfilingRun, because what matters is the shape of @@ -25,6 +27,22 @@ protected function setUp(): void } } + /** + * The factory starts a profiling run, and the Profiler is a singleton for the whole process - so a test + * which builds a tracer would otherwise leave a run recording, which the shutdown function of + * Sandstorm.Plumber writes to disk when the test suite ends. + */ + protected function tearDown(): void + { + if (class_exists(Profiler::class)) { + $instance = new \ReflectionProperty(Profiler::class, 'instance'); + $instance->setAccessible(true); + Profiler::getInstance()->stop(); + $instance->setValue(null, null); + } + parent::tearDown(); + } + public function testNothingConfiguredMeansNoTracer(): void { self::assertInstanceOf(NullTracer::class, $this->buildProvider(null)->getTracer()); @@ -41,6 +59,20 @@ public function testAConfiguredFactoryIsUsed(): void self::assertInstanceOf(PlumberTracer::class, $provider->getTracer()); } + public function testTheFactoryStartsAProfilingRunSoThatOnlyTheRenderingIsProfiled(): void + { + $profiler = Profiler::getInstance(); + $profiler->stop(); + $profiler->setConfigurationProvider(static fn() => ['profilePath' => 'php://memory']); + + $tracer = (new PlumberTracerFactory())->build([]); + $tracer->mark('rendering started'); + + $run = $profiler->stop(); + self::assertInstanceOf(ProfilingRun::class, $run); + self::assertSame(['rendering started'], array_column($run->getTimestamps(), 'name')); + } + public function testAFactoryWhichDoesNotImplementTheInterfaceIsRejected(): void { $this->expectException(\RuntimeException::class); From 1ef1757263d9f67e53205bafc3c32e84424a5936 Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Thu, 27 Aug 2026 13:16:22 +0200 Subject: [PATCH 3/6] make profiles slimmer --- .../NodeRendering/Tracing/PlumberTracer.php | 4 + .../Tracing/PlumberTracerFactory.php | 15 +++- README.md | 9 ++- .../Tracing/PlumberTracerTest.php | 76 +++++++++++++++++++ 4 files changed, 99 insertions(+), 5 deletions(-) diff --git a/Classes/NodeRendering/Tracing/PlumberTracer.php b/Classes/NodeRendering/Tracing/PlumberTracer.php index 9dc90e8..3ab53c3 100644 --- a/Classes/NodeRendering/Tracing/PlumberTracer.php +++ b/Classes/NodeRendering/Tracing/PlumberTracer.php @@ -50,6 +50,10 @@ public function closeSpan(): void 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); } diff --git a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php index b5ebd31..35ff8bf 100644 --- a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php +++ b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php @@ -25,9 +25,16 @@ public function build(array $options): RenderTracerInterface // 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. - return new PlumberTracer( - Profiler::getInstance()->startIfNotRunning(), - (float)($options['minimumDocumentDurationMs'] ?? 0), - ); + $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); } } diff --git a/README.md b/README.md index 8229a88..eaaed26 100644 --- a/README.md +++ b/README.md @@ -746,6 +746,12 @@ Flowpack: minimumDocumentDurationMs: 0 ``` +**Set `minimumDocumentDurationMs` for a full release.** With `0` every render batch writes a profile; one +measured full release of ~36.000 document renders wrote 1817 of them totalling 17 GB - which `/plumber` cannot +list. Above `0` the threshold decides twice: a document faster than it is not recorded, and a batch of 20 +documents in which *nothing* crossed it is not written at all. At 5000 ms that same release would have left +roughly 20 profiles behind, and those are the ones worth opening. A quick release is small enough for `0`. + The shipped implementation needs [sandstorm/plumber](https://github.com/sandstorm/Plumber) (`composer require --dev sandstorm/plumber`) to be installed, but **not** to be switched on. Leave `Sandstorm.Plumber.enabled` at `false`: the factory calls `Profiler::startIfNotRunning()`, so a profiling run @@ -763,7 +769,8 @@ What the resulting profiles look like: * **One profile per render worker run, not per release, and not per document.** A worker restarts itself after 20 documents (`RESTART_AFTER_RENDER_COUNT`), and every restart writes its own profile. A release rendered by four - workers therefore leaves `ceil(documents / 20)` profiles behind. + workers therefore leaves `ceil(documents / 20)` profiles behind - unless `minimumDocumentDurationMs` is set, in + which case only the batches containing a document above the threshold are kept. * All of them carry the tag `contentRelease:` and the run options `Content Release` and `Renderer`, which is how you collect the profiles belonging to one release. * The profile starts with the first document, not with the process, because that is where the run is started. diff --git a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php index 7a386ae..1d1af57 100644 --- a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -19,6 +19,11 @@ */ final class PlumberTracerTest extends UnitTestCase { + /** + * @var list + */ + private array $temporaryProfilePaths = []; + protected function setUp(): void { parent::setUp(); @@ -40,9 +45,25 @@ protected function tearDown(): void Profiler::getInstance()->stop(); $instance->setValue(null, null); } + + foreach ($this->temporaryProfilePaths as $path) { + array_map('unlink', glob($path . '/*') ?: []); + rmdir($path); + } + $this->temporaryProfilePaths = []; + parent::tearDown(); } + private function temporaryProfilePath(): string + { + $path = sys_get_temp_dir() . '/plumber-tracer-test-' . bin2hex(random_bytes(6)); + mkdir($path); + $this->temporaryProfilePaths[] = $path; + + return $path; + } + public function testNothingConfiguredMeansNoTracer(): void { self::assertInstanceOf(NullTracer::class, $this->buildProvider(null)->getTracer()); @@ -114,6 +135,61 @@ public function testADocumentBelowTheThresholdIsNotRecorded(): void self::assertArrayHasKey('slow', $timers); } + public function testABatchWithoutASurvivingSpanIsNotWrittenAtAll(): void + { + $profilePath = $this->temporaryProfilePath(); + + $run = new ProfilingRun(); + $run->start(); + $run->discardUnlessMarkedRelevant(); + $tracer = new PlumberTracer($run, 50.0); + $tracer->openSpan('fast'); + $tracer->closeSpan(); + $run->stop(); + $run->save(['profilePath' => $profilePath]); + + self::assertSame([], glob($profilePath . '/*.profile')); + } + + public function testABatchWithASlowDocumentIsWritten(): void + { + $profilePath = $this->temporaryProfilePath(); + + $run = new ProfilingRun(); + $run->start(); + $run->discardUnlessMarkedRelevant(); + $tracer = new PlumberTracer($run, 50.0); + $tracer->openSpan('slow'); + usleep(60000); + $tracer->closeSpan(); + $run->stop(); + $run->save(['profilePath' => $profilePath]); + + self::assertCount(1, glob($profilePath . '/*.profile')); + self::assertCount(1, glob($profilePath . '/*.meta.json')); + } + + /** + * Without a threshold every batch is interesting, so the run must not be armed - otherwise a release + * configured to record everything would write nothing. + */ + public function testTheFactoryOnlyArmsTheDiscardWhenAThresholdIsConfigured(): void + { + $profilePath = $this->temporaryProfilePath(); + + $profiler = Profiler::getInstance(); + $profiler->stop(); + $profiler->setConfigurationProvider(static fn(): array => ['profilePath' => $profilePath]); + + $tracer = (new PlumberTracerFactory())->build(['minimumDocumentDurationMs' => 0]); + $tracer->openSpan('anything'); + $tracer->closeSpan(); + + $profiler->stopAndSave(); + + self::assertCount(1, glob($profilePath . '/*.profile')); + } + public function testClosingMoreSpansThanWereOpenedIsAnError(): void { $this->expectException(\RuntimeException::class); From dab63efc40844f70e92df4fd5e14ad0cd3ac5017 Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Tue, 1 Sep 2026 11:25:20 +0200 Subject: [PATCH 4/6] add plumber to dev deps --- composer.json | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/composer.json b/composer.json index ce7c012..489d36d 100644 --- a/composer.json +++ b/composer.json @@ -18,7 +18,8 @@ "phpunit/phpunit": "^10.0", "phpstan/extension-installer": "^1.4", "phpstan/phpstan-strict-rules": "^2.0", - "ergebnis/phpstan-rules": "^2.13" + "ergebnis/phpstan-rules": "^2.13", + "sandstorm/plumber": "^4.1" }, "autoload": { "psr-4": { From 78d5f366110aed912666f8b0df6886e44770df6a Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Tue, 1 Sep 2026 14:09:36 +0200 Subject: [PATCH 5/6] fix tests --- .../Tracing/RenderTracerProvider.php | 5 ++- .../Tracing/PlumberTracerTest.php | 35 +++++++++++++------ 2 files changed, 28 insertions(+), 12 deletions(-) diff --git a/Classes/NodeRendering/Tracing/RenderTracerProvider.php b/Classes/NodeRendering/Tracing/RenderTracerProvider.php index 2cd004a..8802f7d 100644 --- a/Classes/NodeRendering/Tracing/RenderTracerProvider.php +++ b/Classes/NodeRendering/Tracing/RenderTracerProvider.php @@ -15,6 +15,9 @@ #[Flow\Scope('singleton')] class RenderTracerProvider { + /** + * @var array{factoryObjectName: ?string, options: ?array{minimumDocumentDurationMs: int}}|null + */ #[Flow\InjectConfiguration('nodeRendering.performanceTracer')] protected ?array $configuration = null; @@ -29,7 +32,7 @@ public function getTracer(): RenderTracerInterface return $this->tracer; } - protected function buildTracer(): RenderTracerInterface + private function buildTracer(): RenderTracerInterface { $factoryObjectName = $this->configuration['factoryObjectName'] ?? null; if (!is_string($factoryObjectName) || $factoryObjectName === '') { diff --git a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php index 1d1af57..d199053 100644 --- a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -6,10 +6,11 @@ use Flowpack\DecoupledContentStore\NodeRendering\Tracing\NullTracer; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracer; +use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerInterface; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerProvider; -use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory; use Neos\Flow\Tests\UnitTestCase; +use ReflectionProperty; use Sandstorm\Plumber\Core\Domain\Model\ProfilingRun; use Sandstorm\Plumber\Core\Profiler; @@ -40,14 +41,16 @@ protected function setUp(): void protected function tearDown(): void { if (class_exists(Profiler::class)) { - $instance = new \ReflectionProperty(Profiler::class, 'instance'); - $instance->setAccessible(true); + $instance = new ReflectionProperty(Profiler::class, 'instance'); Profiler::getInstance()->stop(); $instance->setValue(null, null); } foreach ($this->temporaryProfilePaths as $path) { - array_map('unlink', glob($path . '/*') ?: []); + $fileNames = glob($path . '/*'); + if (is_array($fileNames)) { + array_map('unlink', $fileNames); + } rmdir($path); } $this->temporaryProfilePaths = []; @@ -73,7 +76,7 @@ public function testNothingConfiguredMeansNoTracer(): void public function testAConfiguredFactoryIsUsed(): void { $provider = $this->buildProvider([ - 'factoryObjectName' => \Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory::class, + 'factoryObjectName' => PlumberTracerFactory::class, 'options' => ['minimumDocumentDurationMs' => 0], ]); @@ -89,6 +92,7 @@ public function testTheFactoryStartsAProfilingRunSoThatOnlyTheRenderingIsProfile $tracer = (new PlumberTracerFactory())->build([]); $tracer->mark('rendering started'); + /** @var ProfilingRun|null $run */ $run = $profiler->stop(); self::assertInstanceOf(ProfilingRun::class, $run); self::assertSame(['rendering started'], array_column($run->getTimestamps(), 'name')); @@ -165,8 +169,12 @@ public function testABatchWithASlowDocumentIsWritten(): void $run->stop(); $run->save(['profilePath' => $profilePath]); - self::assertCount(1, glob($profilePath . '/*.profile')); - self::assertCount(1, glob($profilePath . '/*.meta.json')); + $profileFiles = glob($profilePath . '/*.profile'); + self::assertIsArray($profileFiles); + self::assertCount(1, $profileFiles); + $metaFiles = glob($profilePath . '/*.meta.json'); + self::assertIsArray($metaFiles); + self::assertCount(1, $metaFiles); } /** @@ -187,7 +195,9 @@ public function testTheFactoryOnlyArmsTheDiscardWhenAThresholdIsConfigured(): vo $profiler->stopAndSave(); - self::assertCount(1, glob($profilePath . '/*.profile')); + $profileFiles = glob($profilePath . '/*.profile'); + self::assertIsArray($profileFiles); + self::assertCount(1, $profileFiles); } public function testClosingMoreSpansThanWereOpenedIsAnError(): void @@ -214,18 +224,21 @@ public function testTheRunIsTaggedWithTheContentReleaseItRendersFor(): void ); } + /** + * @param array{factoryObjectName: ?string, options: ?array{minimumDocumentDurationMs: int}}|null $configuration + * @return RenderTracerProvider + */ private function buildProvider(?array $configuration): RenderTracerProvider { $provider = new RenderTracerProvider(); - $reflection = new \ReflectionProperty(RenderTracerProvider::class, 'configuration'); - $reflection->setAccessible(true); + $reflection = new ReflectionProperty(RenderTracerProvider::class, 'configuration'); $reflection->setValue($provider, $configuration); return $provider; } /** - * @return array + * @return array */ private function timersByName(ProfilingRun $run): array { From 4410e37fe18c1099c5f6c201c7d39730b4dd2bdd Mon Sep 17 00:00:00 2001 From: Timon Heuser Date: Tue, 1 Sep 2026 14:17:04 +0200 Subject: [PATCH 6/6] fix phpstan --- .../Unit/NodeRendering/Tracing/PlumberTracerTest.php | 12 ++---------- 1 file changed, 2 insertions(+), 10 deletions(-) diff --git a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php index d199053..18a1a90 100644 --- a/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -4,7 +4,6 @@ namespace Flowpack\DecoupledContentStore\Tests\Unit\NodeRendering\Tracing; -use Flowpack\DecoupledContentStore\NodeRendering\Tracing\NullTracer; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracer; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\PlumberTracerFactory; use Flowpack\DecoupledContentStore\NodeRendering\Tracing\RenderTracerInterface; @@ -67,12 +66,6 @@ private function temporaryProfilePath(): string return $path; } - public function testNothingConfiguredMeansNoTracer(): void - { - self::assertInstanceOf(NullTracer::class, $this->buildProvider(null)->getTracer()); - self::assertInstanceOf(NullTracer::class, $this->buildProvider([])->getTracer()); - } - public function testAConfiguredFactoryIsUsed(): void { $provider = $this->buildProvider([ @@ -92,7 +85,6 @@ public function testTheFactoryStartsAProfilingRunSoThatOnlyTheRenderingIsProfile $tracer = (new PlumberTracerFactory())->build([]); $tracer->mark('rendering started'); - /** @var ProfilingRun|null $run */ $run = $profiler->stop(); self::assertInstanceOf(ProfilingRun::class, $run); self::assertSame(['rendering started'], array_column($run->getTimestamps(), 'name')); @@ -225,7 +217,7 @@ public function testTheRunIsTaggedWithTheContentReleaseItRendersFor(): void } /** - * @param array{factoryObjectName: ?string, options: ?array{minimumDocumentDurationMs: int}}|null $configuration + * @param array{factoryObjectName?: ?string, options?: ?array{minimumDocumentDurationMs: int}}|null $configuration * @return RenderTracerProvider */ private function buildProvider(?array $configuration): RenderTracerProvider @@ -243,7 +235,7 @@ private function buildProvider(?array $configuration): RenderTracerProvider private function timersByName(ProfilingRun $run): array { $timers = []; - foreach ($run->getTimersAsDuration() as $timer) { + foreach ($run->getTimersAsDuration() ?? [] as $timer) { $timers[$timer['name']] = $timer; } unset($timers['Profiling Run']);