From f7a4d02a331e8cbbf9953bf3af6e804414b9af3e Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 12:42:26 +0000 Subject: [PATCH 1/6] Made helper class to fetch request headers consistently --- src/Helper/FetchRequestHeaders.php | 71 +++++++++++++++++++ tests/Unit/Helper/FetchRequestHeadersTest.php | 43 +++++++++++ 2 files changed, 114 insertions(+) create mode 100644 src/Helper/FetchRequestHeaders.php create mode 100644 tests/Unit/Helper/FetchRequestHeadersTest.php 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/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; + } +} From b4e1ccccc216e464b8a62e5f99e10d9d2c8e7175 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 15:16:48 +0000 Subject: [PATCH 2/6] Started working on tagRequest if we have queue time method --- src/Events/Request/Request.php | 14 ++++++++++++++ src/Events/Tag/Tag.php | 1 + 2 files changed, 15 insertions(+) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 9aa1221b..b458d044 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -10,6 +10,7 @@ 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; @@ -69,6 +70,19 @@ 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)) { + $headerValue = $headers[$headerToCheck]; + // @todo header value format? +// $this->tag(Tag::TAG_QUEUE_TIME, $queueTime); + } + } + } + public function stopIfRunning() : void { if ($this->timer->getStop() !== null) { 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; From aa7313f5ea86a33da6118e082c452eeae9d36f0e Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 15:56:28 +0000 Subject: [PATCH 3/6] Added tag for amount of time in request queue from header --- src/Events/Request/Request.php | 12 +++++++---- src/Helper/Timer.php | 5 +++++ tests/Unit/Events/Request/RequestTest.php | 26 +++++++++++++++++++++++ tests/Unit/Helper/TimerTest.php | 1 + 4 files changed, 40 insertions(+), 4 deletions(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index b458d044..b3de7c29 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -14,6 +14,7 @@ use Scoutapm\Helper\MemoryUsage; use Scoutapm\Helper\RecursivelyCountSpans; use Scoutapm\Helper\Timer; +use function array_key_exists; use function is_string; /** @internal */ @@ -75,11 +76,12 @@ private function tagRequestIfRequestQueueTimeHeaderExists() : void $headers = FetchRequestHeaders::fromServerGlobal(); foreach (['X-Queue-Start', 'X-Request-Start'] as $headerToCheck) { - if (array_key_exists($headerToCheck, $headers)) { - $headerValue = $headers[$headerToCheck]; - // @todo header value format? -// $this->tag(Tag::TAG_QUEUE_TIME, $queueTime); + if (! array_key_exists($headerToCheck, $headers)) { + continue; } + + $headerValue = (float) $headers[$headerToCheck] / 10000; + $this->tag(Tag::TAG_QUEUE_TIME, $this->timer->getStartAsMicrotime() - $headerValue); } } @@ -98,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/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..378937fa 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -9,11 +9,14 @@ 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; +use function str_replace; use function time; /** @covers \Scoutapm\Events\Request\Request */ @@ -157,4 +160,27 @@ public function testSpansCanBeCounted() : void self::assertSame(2, $request->collectedSpans()); } + + public function testRequestIsTaggedWithQueueTime() : void + { + $_SERVER['HTTP_X_REQUEST_START'] = str_replace('.', '', (string) (microtime(true) - 2)); + + $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(1.9, $command['TagRequest']['value']); + self::assertLessThanOrEqual(2.1, $command['TagRequest']['value']); + $foundTag = true; + } + + self::assertTrue($foundTag, 'Could not find queue time tag'); + } } 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 From 728c66997fd68607d39b3cc3656c6555b4b78659 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 16:05:26 +0000 Subject: [PATCH 4/6] Convert queue time to nanoseconds --- src/Events/Request/Request.php | 2 +- tests/Unit/Events/Request/RequestTest.php | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index b3de7c29..d5efb964 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -81,7 +81,7 @@ private function tagRequestIfRequestQueueTimeHeaderExists() : void } $headerValue = (float) $headers[$headerToCheck] / 10000; - $this->tag(Tag::TAG_QUEUE_TIME, $this->timer->getStartAsMicrotime() - $headerValue); + $this->tag(Tag::TAG_QUEUE_TIME, ($this->timer->getStartAsMicrotime() - $headerValue) * 1e9); } } diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 378937fa..760413ca 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -176,8 +176,8 @@ public function testRequestIsTaggedWithQueueTime() : void continue; } - self::assertGreaterThanOrEqual(1.9, $command['TagRequest']['value']); - self::assertLessThanOrEqual(2.1, $command['TagRequest']['value']); + self::assertGreaterThanOrEqual(1900000000, $command['TagRequest']['value']); + self::assertLessThanOrEqual(2100000000, $command['TagRequest']['value']); $foundTag = true; } From c26eb432f8264216cf5ae01032daf31c0628aed4 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 16:16:20 +0000 Subject: [PATCH 5/6] Unset HTTP_X_REQUEST_START so other tests are not affected --- tests/Unit/Events/Request/RequestTest.php | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 760413ca..73c02c0f 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -182,5 +182,7 @@ public function testRequestIsTaggedWithQueueTime() : void } self::assertTrue($foundTag, 'Could not find queue time tag'); + + unset($_SERVER['HTTP_X_REQUEST_START']); } } From 62aba87322f2e35cf80bb866fe23a88d9cb84544 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 19 Dec 2019 16:29:27 +0000 Subject: [PATCH 6/6] Don't drop significant decimal digits --- tests/Unit/Events/Request/RequestTest.php | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 73c02c0f..aa94d3d9 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -16,7 +16,6 @@ use function next; use function reset; use function str_repeat; -use function str_replace; use function time; /** @covers \Scoutapm\Events\Request\Request */ @@ -163,7 +162,7 @@ public function testSpansCanBeCounted() : void public function testRequestIsTaggedWithQueueTime() : void { - $_SERVER['HTTP_X_REQUEST_START'] = str_replace('.', '', (string) (microtime(true) - 2)); + $_SERVER['HTTP_X_REQUEST_START'] = (string) ((microtime(true) - 2) * 10000); $request = new Request(); $request->stop();