From 7665553194e0cbec56446add186702559ac442c5 Mon Sep 17 00:00:00 2001 From: Cyril Vermande Date: Sat, 22 Oct 2022 20:29:50 +0200 Subject: [PATCH] feat: add kernel boot time as tracing attribute --- .../EventSubscriber/CommandEventSubscriberSpec.php | 6 +++--- .../EventSubscriber/RequestEventSubscriberSpec.php | 4 ++-- .../EventSubscriber/CommandEventSubscriber.php | 5 ++++- .../EventSubscriber/RequestEventSubscriber.php | 7 +++---- 4 files changed, 12 insertions(+), 10 deletions(-) diff --git a/spec/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriberSpec.php b/spec/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriberSpec.php index 9fba455..6f664d1 100644 --- a/spec/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriberSpec.php +++ b/spec/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriberSpec.php @@ -57,7 +57,7 @@ public function it_starts_new_span_when_receiving_event_for_a_named_command( $this->onCommand($this->createConsoleCommandEvent(new Command('test:cmd'))); $tracer->spanBuilder('cli test:cmd')->shouldHaveBeenCalled(); - $spanBuilder->setAttributes(['command' => 'test:cmd'])->shouldHaveBeenCalled(); + $spanBuilder->setAttributes(Argument::allOf(Argument::withEntry('command', 'test:cmd'), Argument::withKey('sf.kernel_boot_duration')))->shouldHaveBeenCalled(); $span->activate()->shouldHaveBeenCalled(); expect($this->mainSpanContext->getMainSpan())->shouldBe($span); } @@ -70,7 +70,7 @@ public function it_starts_new_span_when_receiving_event_for_an_unnamed_command( $this->onCommand($this->createConsoleCommandEvent(new Command())); $tracer->spanBuilder('cli unknown-command')->shouldHaveBeenCalled(); - $spanBuilder->setAttributes(['command' => 'unknown-command'])->shouldHaveBeenCalled(); + $spanBuilder->setAttributes(Argument::allOf(Argument::withEntry('command', 'unknown-command'), Argument::withKey('sf.kernel_boot_duration')))->shouldHaveBeenCalled(); $span->activate()->shouldHaveBeenCalled(); expect($this->mainSpanContext->getMainSpan())->shouldBe($span); } @@ -83,7 +83,7 @@ public function it_starts_new_span_when_receiving_event_without_a_command( $this->onCommand($this->createConsoleCommandEvent()); $tracer->spanBuilder('cli unknown-command')->shouldHaveBeenCalled(); - $spanBuilder->setAttributes(['command' => 'unknown-command'])->shouldHaveBeenCalled(); + $spanBuilder->setAttributes(Argument::allOf(Argument::withEntry('command', 'unknown-command'), Argument::withKey('sf.kernel_boot_duration')))->shouldHaveBeenCalled(); $span->activate()->shouldHaveBeenCalled(); expect($this->mainSpanContext->getMainSpan())->shouldBe($span); } diff --git a/spec/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriberSpec.php b/spec/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriberSpec.php index 86687c1..8539bdd 100644 --- a/spec/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriberSpec.php +++ b/spec/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriberSpec.php @@ -80,7 +80,7 @@ public function let( $serverSpanBuilder->startSpan()->willReturn($serverSpan); $serverSpan->activate()->willReturn($serverScope); $serverSpan->updateName(Argument::type('string'))->willReturn($serverSpan); - $serverSpan->setAttributes($this->requestAttributes)->willReturn($serverSpan); + $serverSpan->setAttributes(Argument::withKey('request'))->willReturn($serverSpan); $serverSpan->setAttribute(Argument::cetera())->willReturn($serverSpan); $serverSpan->setStatus(Argument::cetera())->willReturn($serverSpan); $serverScope->detach()->willReturn(0); @@ -112,7 +112,7 @@ public function it_creates_server_span_and_request_span_when_receiving_request_f $serverSpanBuilder->setStartTimestamp($startTime * 1000 ** 3)->shouldHaveBeenCalled(); $serverSpan->activate()->shouldHaveBeenCalled(); $serverSpan->updateName('http.put /test/{id}')->shouldHaveBeenCalled(); - $serverSpan->setAttributes($this->requestAttributes)->shouldHaveBeenCalled(); + $serverSpan->setAttributes(Argument::allOf(Argument::withEntry('request', 'attribute'), Argument::withKey('sf.kernel_boot_duration')))->shouldHaveBeenCalled(); expect($this->mainSpanContext->getMainSpan())->shouldBe($serverSpan); $requestSpan->activate()->shouldHaveBeenCalled(); } diff --git a/src/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriber.php b/src/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriber.php index 9ef12d2..ec9099d 100644 --- a/src/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriber.php +++ b/src/Tracing/Instrumentation/EventSubscriber/CommandEventSubscriber.php @@ -46,7 +46,10 @@ public function onCommand(ConsoleCommandEvent $event): void { $name = $event->getCommand()?->getName() ?: 'unknown-command'; - $this->span = $this->startSpan(sprintf('cli %s', $name), ['command' => $name]); + $startTime = $_SERVER['REQUEST_TIME_FLOAT'] ?? microtime(true); // Float with microsecond precision + $kernelBootTime = round(microtime(true) - $startTime, 3); + + $this->span = $this->startSpan(sprintf('cli %s', $name), ['command' => $name, 'sf.kernel_boot_duration' => $kernelBootTime]); $this->scope = $this->span->activate(); $this->mainSpanContext->setMainSpan($this->span); diff --git a/src/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriber.php b/src/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriber.php index 64d4292..47a5eeb 100644 --- a/src/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriber.php +++ b/src/Tracing/Instrumentation/EventSubscriber/RequestEventSubscriber.php @@ -69,14 +69,12 @@ public function __construct( public function onRequestEvent(Event\RequestEvent $event): void { $request = $event->getRequest(); + $startTime = $request->server->get('REQUEST_TIME_FLOAT'); // Float with microsecond precision if (!$this->serverSpan) { - $startTime = $request->server->get('REQUEST_TIME_FLOAT'); // Float with microsecond precision - $startTime = (int) ($startTime * 1000 * 1000 * 1000); // Convert to nanoseconds - $this->serverSpan = $this->getTracer()->spanBuilder('server') ->setSpanKind(SpanKind::KIND_SERVER) - ->setStartTimestamp($startTime) + ->setStartTimestamp((int) ($startTime * 1000 * 1000 * 1000)) // Convert to nanoseconds ->startSpan(); $this->serverScope = $this->serverSpan->activate(); @@ -86,6 +84,7 @@ public function onRequestEvent(Event\RequestEvent $event): void if ($event->isMainRequest()) { $attributes = $this->requestAttributeProvider->getAttributes($request); + $attributes['sf.kernel_boot_duration'] = round(microtime(true) - $startTime, 3); $this->serverSpan->updateName(sprintf('http.%s %s', strtolower($request->getMethod()), $request->getPathInfo())); $this->serverSpan->setAttributes($attributes);