diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 9aa1221b..d5efb964 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -10,9 +10,11 @@ use Scoutapm\Events\Span\Span; use Scoutapm\Events\Tag\Tag; use Scoutapm\Events\Tag\TagRequest; +use Scoutapm\Helper\FetchRequestHeaders; use Scoutapm\Helper\MemoryUsage; use Scoutapm\Helper\RecursivelyCountSpans; use Scoutapm\Helper\Timer; +use function array_key_exists; use function is_string; /** @internal */ @@ -69,6 +71,20 @@ private function determineRequestPathFromServerGlobal() : string return '/'; } + private function tagRequestIfRequestQueueTimeHeaderExists() : void + { + $headers = FetchRequestHeaders::fromServerGlobal(); + + foreach (['X-Queue-Start', 'X-Request-Start'] as $headerToCheck) { + if (! array_key_exists($headerToCheck, $headers)) { + continue; + } + + $headerValue = (float) $headers[$headerToCheck] / 10000; + $this->tag(Tag::TAG_QUEUE_TIME, ($this->timer->getStartAsMicrotime() - $headerValue) * 1e9); + } + } + public function stopIfRunning() : void { if ($this->timer->getStop() !== null) { @@ -84,6 +100,8 @@ public function stop(?float $overrideTimestamp = null) : void $this->tag(Tag::TAG_MEMORY_DELTA, MemoryUsage::record()->usedDifferenceInMegabytes($this->startMemory)); $this->tag(Tag::TAG_REQUEST_PATH, $this->requestUriOverride ?? $this->determineRequestPathFromServerGlobal()); + + $this->tagRequestIfRequestQueueTimeHeaderExists(); } /** @throws Exception */ diff --git a/src/Events/Tag/Tag.php b/src/Events/Tag/Tag.php index 41b0cce3..e2a2931d 100644 --- a/src/Events/Tag/Tag.php +++ b/src/Events/Tag/Tag.php @@ -15,6 +15,7 @@ abstract class Tag implements Command public const TAG_ARGUMENTS = 'args'; public const TAG_MEMORY_DELTA = 'memory_delta'; public const TAG_REQUEST_PATH = 'path'; + public const TAG_QUEUE_TIME = 'scout.queue_time_ns'; /** @var RequestId */ protected $requestId; diff --git a/src/Helper/FetchRequestHeaders.php b/src/Helper/FetchRequestHeaders.php new file mode 100644 index 00000000..c1616681 --- /dev/null +++ b/src/Helper/FetchRequestHeaders.php @@ -0,0 +1,71 @@ + */ + public static function fromServerGlobal() : array + { + return self::fromArray($_SERVER); + } + + /** + * @param array $server + * + * @return array + */ + private static function fromArray(array $server) : array + { + $qualifyingServerKeys = self::onlyQualifyingServerItems($server); + + return array_combine( + array_map( + static function (string $key) : string { + return ucwords(str_replace('_', '-', strtolower(substr($key, 5))), '-'); + }, + array_keys($qualifyingServerKeys) + ), + $qualifyingServerKeys + ); + } + + /** + * @param array $server + * + * @return array + * + * @psalm-suppress InvalidReturnType + */ + private static function onlyQualifyingServerItems(array $server) : array + { + /** @psalm-suppress InvalidReturnStatement */ + return array_filter( + $server, + /** + * @param mixed $value + * @param mixed $key + */ + static function ($value, $key) : bool { + return is_string($key) + && $value !== '' + && strpos($key, 'HTTP_') === 0; + }, + ARRAY_FILTER_USE_BOTH + ); + } +} diff --git a/src/Helper/Timer.php b/src/Helper/Timer.php index 81bfc04b..8291a3eb 100644 --- a/src/Helper/Timer.php +++ b/src/Helper/Timer.php @@ -74,6 +74,11 @@ public function getStart() : ?string return $timestamp->format(self::FORMAT_FOR_CORE_AGENT); } + public function getStartAsMicrotime() : float + { + return $this->start; + } + /** * Returns the duration in microseconds. If the timer has not yet been stopped yet, `null` is returned. */ diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 6afe8cfa..aa94d3d9 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -9,8 +9,10 @@ use Scoutapm\Events\Request\Request; use Scoutapm\Events\Request\RequestId; use Scoutapm\Events\Span\Span; +use function array_key_exists; use function json_decode; use function json_encode; +use function microtime; use function next; use function reset; use function str_repeat; @@ -157,4 +159,29 @@ public function testSpansCanBeCounted() : void self::assertSame(2, $request->collectedSpans()); } + + public function testRequestIsTaggedWithQueueTime() : void + { + $_SERVER['HTTP_X_REQUEST_START'] = (string) ((microtime(true) - 2) * 10000); + + $request = new Request(); + $request->stop(); + + $f = $request->jsonSerialize(); + + $foundTag = false; + foreach ($f['BatchCommand']['commands'] as $command) { + if (! array_key_exists('TagRequest', $command) || $command['TagRequest']['tag'] !== 'scout.queue_time_ns') { + continue; + } + + self::assertGreaterThanOrEqual(1900000000, $command['TagRequest']['value']); + self::assertLessThanOrEqual(2100000000, $command['TagRequest']['value']); + $foundTag = true; + } + + self::assertTrue($foundTag, 'Could not find queue time tag'); + + unset($_SERVER['HTTP_X_REQUEST_START']); + } } diff --git a/tests/Unit/Helper/FetchRequestHeadersTest.php b/tests/Unit/Helper/FetchRequestHeadersTest.php new file mode 100644 index 00000000..174789ea --- /dev/null +++ b/tests/Unit/Helper/FetchRequestHeadersTest.php @@ -0,0 +1,43 @@ + $oldServer['SCRIPT_NAME'], // Needed for PHPUnit + 'REQUEST_TIME' => $oldServer['REQUEST_TIME'], // Needed for PHPUnit + 'DOCUMENT_ROOT' => '/path/to/public', + 'REMOTE_ADDR' => '127.0.0.1', + 'HTTP_HOST' => 'scout-apm-test', + 'HTTP_USER_AGENT' => 'Scout APM test', + 'HTTP_COOKIE' => 'cookie_a=null; cookie_b=null', + 'HTTP_ACCEPT' => '*/*', + 'HTTP_X_SOMETHING_EMPTY' => '', + 'HTTP_X_SOMETHING_CUSTOM' => 'Something custom', + 0 => 'should be dismissed', + 1 => '', + ]; + + self::assertEquals( + [ + 'Host' => 'scout-apm-test', + 'User-Agent' => 'Scout APM test', + 'Cookie' => 'cookie_a=null; cookie_b=null', + 'Accept' => '*/*', + 'X-Something-Custom' => 'Something custom', + ], + FetchRequestHeaders::fromServerGlobal() + ); + $_SERVER = $oldServer; + } +} diff --git a/tests/Unit/Helper/TimerTest.php b/tests/Unit/Helper/TimerTest.php index c9ea8e4a..141c2b13 100644 --- a/tests/Unit/Helper/TimerTest.php +++ b/tests/Unit/Helper/TimerTest.php @@ -22,6 +22,7 @@ public function testCreatingTheTimerSetsStartTime() : void { $timer = new Timer(); self::assertNotNull($timer->getStart()); + self::assertIsFloat($timer->getStartAsMicrotime()); } public function testStoppingSetsStopTime() : void