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; + } + + // 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); + } + } +} diff --git a/Classes/NodeRendering/Tracing/PlumberTracerFactory.php b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php new file mode 100644 index 0000000..35ff8bf --- /dev/null +++ b/Classes/NodeRendering/Tracing/PlumberTracerFactory.php @@ -0,0 +1,40 @@ +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/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..8802f7d --- /dev/null +++ b/Classes/NodeRendering/Tracing/RenderTracerProvider.php @@ -0,0 +1,56 @@ +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'] ?? []); + } +} 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..eaaed26 100644 --- a/README.md +++ b/README.md @@ -729,6 +729,57 @@ 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 +``` + +**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 +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. + +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 - 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. + 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. + ### 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..18a1a90 --- /dev/null +++ b/Tests/Unit/NodeRendering/Tracing/PlumberTracerTest.php @@ -0,0 +1,245 @@ + + */ + private array $temporaryProfilePaths = []; + + protected function setUp(): void + { + parent::setUp(); + if (!class_exists(ProfilingRun::class)) { + self::markTestSkipped('sandstorm/plumber is an optional dependency and is not installed.'); + } + } + + /** + * 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'); + Profiler::getInstance()->stop(); + $instance->setValue(null, null); + } + + foreach ($this->temporaryProfilePaths as $path) { + $fileNames = glob($path . '/*'); + if (is_array($fileNames)) { + array_map('unlink', $fileNames); + } + 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 testAConfiguredFactoryIsUsed(): void + { + $provider = $this->buildProvider([ + 'factoryObjectName' => PlumberTracerFactory::class, + 'options' => ['minimumDocumentDurationMs' => 0], + ]); + + 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); + $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 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]); + + $profileFiles = glob($profilePath . '/*.profile'); + self::assertIsArray($profileFiles); + self::assertCount(1, $profileFiles); + $metaFiles = glob($profilePath . '/*.meta.json'); + self::assertIsArray($metaFiles); + self::assertCount(1, $metaFiles); + } + + /** + * 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(); + + $profileFiles = glob($profilePath . '/*.profile'); + self::assertIsArray($profileFiles); + self::assertCount(1, $profileFiles); + } + + 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(), + ); + } + + /** + * @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->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..489d36d 100644 --- a/composer.json +++ b/composer.json @@ -9,13 +9,17 @@ "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", "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": {