diff --git a/src/Profiling/ContinuousProfiler.php b/src/Profiling/ContinuousProfiler.php index c7b21ed67..a98d8a535 100644 --- a/src/Profiling/ContinuousProfiler.php +++ b/src/Profiling/ContinuousProfiler.php @@ -54,6 +54,11 @@ final class ContinuousProfiler */ private $sampled; + /** + * @var array The span IDs of the sampled root spans the profiler is running for + */ + private $activeRootSpans = []; + /** * @var int */ @@ -132,6 +137,31 @@ public function start(): void $profiler->start(); } + /** + * Starts the profiler for a sampled root span, it keeps running until all of them are finished. + */ + public function startForRootSpan(string $spanId): void + { + $this->start(); + + if ($this->profiler !== null) { + $this->activeRootSpans[$spanId] = true; + } + } + + public function stopForRootSpan(string $spanId): void + { + if (!isset($this->activeRootSpans[$spanId])) { + return; + } + + unset($this->activeRootSpans[$spanId]); + + if ($this->activeRootSpans === []) { + $this->stop(); + } + } + public function stop(): void { if ($this->profiler === null) { @@ -146,6 +176,7 @@ public function stop(): void $this->profiler = null; $this->profilerId = null; $this->startTimestamp = null; + $this->activeRootSpans = []; } public function isRunning(): bool diff --git a/src/State/Hub.php b/src/State/Hub.php index a1d8f13ea..2d80d3e66 100644 --- a/src/State/Hub.php +++ b/src/State/Hub.php @@ -15,6 +15,8 @@ use Sentry\EventId; use Sentry\Integration\IntegrationInterface; use Sentry\MonitorConfig; +use Sentry\Profiling\ProfileChunk; +use Sentry\Profiling\Profiles; use Sentry\Severity; use Sentry\Tracing\SamplingContext; use Sentry\Tracing\Span; @@ -282,6 +284,10 @@ public function startTransaction(TransactionContext $context, array $customSampl $logger->warning(\sprintf('Transaction [%s] was started but tracing is not enabled.', (string) $transaction->getTraceId()), ['context' => $context]); + if ($options !== null && $options->getProfileLifecycle() === 'trace') { + $logger->warning('The "profile_lifecycle" option is set to "trace" but tracing is not enabled, so no profiles will be collected.'); + } + return $transaction; } @@ -354,6 +360,22 @@ public function startTransaction(TransactionContext $context, array $customSampl $transaction->initSpanRecorder(); + if ($options->getProfileLifecycle() === 'trace') { + $continuousProfiler = Profiles::getInstance()->continuousProfiler(); + $continuousProfiler->startForRootSpan((string) $transaction->getSpanId()); + + $profilerId = $continuousProfiler->getProfilerId(); + + // Backfill profiling data because the profiler was started after the transaction + if ($profilerId !== null) { + $transaction->setData([ + 'thread.id' => ProfileChunk::THREAD_ID, + 'thread.name' => ProfileChunk::THREAD_NAME, + 'profiler_id' => $profilerId, + ]); + } + } + $profilesSampleSource = 'config:profiles_sample_rate'; $profilesSampler = $options->getProfilesSampler(); diff --git a/src/Tracing/Transaction.php b/src/Tracing/Transaction.php index dd568e045..74f6fae3f 100644 --- a/src/Tracing/Transaction.php +++ b/src/Tracing/Transaction.php @@ -7,6 +7,7 @@ use Sentry\Event; use Sentry\EventId; use Sentry\Profiling\Profiler; +use Sentry\Profiling\Profiles; use Sentry\SentrySdk; use Sentry\State\HubInterface; @@ -152,6 +153,8 @@ public function finish(?float $endTimestamp = null): ?EventId $this->profiler->stop(); } + Profiles::getInstance()->continuousProfiler()->stopForRootSpan((string) $this->getSpanId()); + if ($this->endTimestamp !== null) { // Transaction was already finished once and we don't want to re-flush it return null; diff --git a/tests/State/HubTest.php b/tests/State/HubTest.php index e2763aa82..8be476291 100644 --- a/tests/State/HubTest.php +++ b/tests/State/HubTest.php @@ -9,6 +9,7 @@ use Sentry\Breadcrumb; use Sentry\CheckIn; use Sentry\CheckInStatus; +use Sentry\Client; use Sentry\ClientInterface; use Sentry\Event; use Sentry\EventHint; @@ -17,10 +18,14 @@ use Sentry\MonitorConfig; use Sentry\MonitorSchedule; use Sentry\Options; +use Sentry\Profiling\Profiles; +use Sentry\SentrySdk; use Sentry\Severity; use Sentry\State\Hub; +use Sentry\State\HubInterface; use Sentry\State\Scope; use Sentry\Tests\StubLogger; +use Sentry\Tests\StubTransport; use Sentry\Tracing\DynamicSamplingContext; use Sentry\Tracing\PropagationContext; use Sentry\Tracing\SamplingContext; @@ -1115,4 +1120,98 @@ public function testEventTraceContextIsNotOverridenWhenPresent(): void $this->assertEquals($event->getContexts()['trace'], $traceContext); }); } + + /** + * @requires extension excimer + */ + public function testStartTransactionProfilesSampledTransactionsInTraceLifecycle(): void + { + StubTransport::$events = []; + + $hub = $this->initHubWithProfileLifecycleTrace(); + $profiler = Profiles::getInstance()->continuousProfiler(); + + $transaction = $hub->startTransaction(TransactionContext::make()); + + $this->assertTrue($profiler->isRunning()); + + $profilerId = $profiler->getProfilerId(); + + $this->assertSame($profilerId, $transaction->getData('profiler_id')); + + self::busyWait(0.05); + + $transaction->finish(); + + $this->assertFalse($profiler->isRunning()); + $this->assertCount(2, StubTransport::$events); + + [$chunkEvent, $transactionEvent] = StubTransport::$events; + + $this->assertNotNull($chunkEvent->getProfileChunk()); + $this->assertSame($profilerId, $chunkEvent->getProfileChunk()->getProfilerId()); + $this->assertSame(['profiler_id' => $profilerId], $transactionEvent->getContexts()['profile']); + } + + /** + * @requires extension excimer + */ + public function testContinuousProfilerRunsUntilTheLastSampledTransactionIsFinished(): void + { + StubTransport::$events = []; + + $hub = $this->initHubWithProfileLifecycleTrace(); + $profiler = Profiles::getInstance()->continuousProfiler(); + + $firstTransaction = $hub->startTransaction(TransactionContext::make()); + $secondTransaction = $hub->startTransaction(TransactionContext::make()); + + $profilerId = $profiler->getProfilerId(); + + self::busyWait(0.05); + $firstFinishTimestamp = microtime(true); + + $firstTransaction->finish(); + + $this->assertTrue($profiler->isRunning()); + $this->assertSame($profilerId, $profiler->getProfilerId()); + + self::busyWait(0.05); + + $secondTransaction->finish(); + + $this->assertFalse($profiler->isRunning()); + + $chunkEvents = array_values(array_filter(StubTransport::$events, static function (Event $event): bool { + return $event->getProfileChunk() !== null; + })); + + $this->assertCount(1, $chunkEvents); + + $payload = $chunkEvents[0]->getProfileChunk()->getFormattedData($chunkEvents[0]); + + $this->assertNotNull($payload); + $this->assertLessThan($firstFinishTimestamp, $payload['profile']['samples'][0]['timestamp']); + } + + private function initHubWithProfileLifecycleTrace(): HubInterface + { + $hub = SentrySdk::init(); + $hub->bindClient(new Client(new Options([ + 'traces_sample_rate' => 1.0, + 'profile_lifecycle' => 'trace', + 'profile_session_sample_rate' => 1.0, + ]), StubTransport::getInstance())); + + return $hub; + } + + private static function busyWait(float $seconds): void + { + $end = microtime(true) + $seconds; + + while (microtime(true) < $end) { + // Burn CPU so that Excimer collects samples + } + } }