From 6942e356ed2b1bf0bca28fc6ab00b90fb5e13611 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 20 Feb 2020 11:01:48 +0000 Subject: [PATCH 1/6] Allow request start time to be overridden --- src/Events/Request/Request.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 0191635f..3ee3577f 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -40,11 +40,11 @@ class Request implements CommandWithChildren private $requestUriOverride; /** @throws Exception */ - public function __construct() + public function __construct(?float $override = null) { $this->id = RequestId::new(); - $this->timer = new Timer(); + $this->timer = new Timer($override); $this->startMemory = MemoryUsage::record(); $this->currentCommand = $this; From 4249977b1ee9703da1a85ee5f919a49aedc9a7e1 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 20 Feb 2020 11:03:01 +0000 Subject: [PATCH 2/6] Fixed test expectations in testRequestIsTaggedWithQueueTime to be exact rather than approximation --- tests/Integration/AgentTest.php | 1 + tests/Unit/Events/Request/RequestTest.php | 11 ++++++----- 2 files changed, 7 insertions(+), 5 deletions(-) diff --git a/tests/Integration/AgentTest.php b/tests/Integration/AgentTest.php index 6b1326c1..bdd0be4a 100644 --- a/tests/Integration/AgentTest.php +++ b/tests/Integration/AgentTest.php @@ -18,6 +18,7 @@ use function function_exists; use function getenv; use function gethostname; +use function meminfo_dump; use function memory_get_usage; use function next; use function reset; diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index aa94d3d9..025f6e58 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -12,7 +12,6 @@ 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; @@ -162,9 +161,11 @@ public function testSpansCanBeCounted() : void public function testRequestIsTaggedWithQueueTime() : void { - $_SERVER['HTTP_X_REQUEST_START'] = (string) ((microtime(true) - 2) * 10000); + // 2 = 2ms after epoch + $_SERVER['HTTP_X_REQUEST_START'] = '2'; - $request = new Request(); + // 0.005 = 5ms after epoch + $request = new Request(0.005); $request->stop(); $f = $request->jsonSerialize(); @@ -175,8 +176,8 @@ public function testRequestIsTaggedWithQueueTime() : void continue; } - self::assertGreaterThanOrEqual(1900000000, $command['TagRequest']['value']); - self::assertLessThanOrEqual(2100000000, $command['TagRequest']['value']); + // queue time should be 3ms (represented as 3000000 nanoseconds, as a float) + self::assertSame(3000000.0, $command['TagRequest']['value']); $foundTag = true; } From 9cffe178ecf776f945aa05fc0e87214ee4d71b7e Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Thu, 20 Feb 2020 11:03:20 +0000 Subject: [PATCH 3/6] Fixed bug in tagRequestIfRequestQueueTimeHeaderExists calculation for request queue time --- src/Events/Request/Request.php | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 3ee3577f..6308bbff 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -92,7 +92,10 @@ private function tagRequestIfRequestQueueTimeHeaderExists() : void continue; } - $headerValue = (float) $headers[$headerToCheck] / 10000; + // Header comes in as milliseconds, so divide by 1,000 to get value in seconds + $headerValue = (float) $headers[$headerToCheck] / 1000; + + // Time tags should be in nanoseconds, so multiply seconds by 1e9 (1,000,000,000) $this->tag(Tag::TAG_QUEUE_TIME, ($this->timer->getStartAsMicrotime() - $headerValue) * 1e9); } } From 7898e598d4a267f2240bbcb7e9e7dfe1bf2e49a0 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Tue, 3 Mar 2020 09:25:06 +0000 Subject: [PATCH 4/6] Handle cases where header can start with t= --- src/Events/Request/Request.php | 15 +++++++++++++-- tests/Unit/Events/Request/RequestTest.php | 23 ++++++++++++++++++++--- 2 files changed, 33 insertions(+), 5 deletions(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index 6308bbff..b483fede 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -17,6 +17,8 @@ use function array_key_exists; use function array_map; use function is_string; +use function strpos; +use function substr; /** @internal */ class Request implements CommandWithChildren @@ -92,11 +94,20 @@ private function tagRequestIfRequestQueueTimeHeaderExists() : void continue; } + $headerValue = $headers[$headerToCheck]; + + if (strpos($headerValue, 't=') === 0) { + $headerValue = substr($headerValue, 2); + } + // Header comes in as milliseconds, so divide by 1,000 to get value in seconds - $headerValue = (float) $headers[$headerToCheck] / 1000; + $headerValueInSeconds = (float) $headerValue / 1000; // Time tags should be in nanoseconds, so multiply seconds by 1e9 (1,000,000,000) - $this->tag(Tag::TAG_QUEUE_TIME, ($this->timer->getStartAsMicrotime() - $headerValue) * 1e9); + $this->tag( + Tag::TAG_QUEUE_TIME, + ($this->timer->getStartAsMicrotime() - $headerValueInSeconds) * 1e9 + ); } } diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 025f6e58..87f643fa 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -14,6 +14,7 @@ use function json_encode; use function next; use function reset; +use function sprintf; use function str_repeat; use function time; @@ -159,10 +160,26 @@ public function testSpansCanBeCounted() : void self::assertSame(2, $request->collectedSpans()); } - public function testRequestIsTaggedWithQueueTime() : void + /** @return string[][] */ + public function queueTimeRequestHeadersProvider() : array + { + return [ + ['HTTP_X_REQUEST_START', '%d'], + ['HTTP_X_REQUEST_START', 't=%d'], + ['HTTP_X_QUEUE_START', '%d'], + ['HTTP_X_QUEUE_START', 't=%d'], + ]; + } + + /** + * @throws Exception + * + * @dataProvider queueTimeRequestHeadersProvider + */ + public function testRequestIsTaggedWithQueueTime(string $headerName, string $headerValueFormat) : void { // 2 = 2ms after epoch - $_SERVER['HTTP_X_REQUEST_START'] = '2'; + $_SERVER[$headerName] = sprintf($headerValueFormat, 2); // 0.005 = 5ms after epoch $request = new Request(0.005); @@ -183,6 +200,6 @@ public function testRequestIsTaggedWithQueueTime() : void self::assertTrue($foundTag, 'Could not find queue time tag'); - unset($_SERVER['HTTP_X_REQUEST_START']); + unset($_SERVER[$headerName]); } } From 917edb926b0fec1cddb244eb70cfe8caf460a75d Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Tue, 3 Mar 2020 10:04:26 +0000 Subject: [PATCH 5/6] Updated Request->stop() to take current time as an optional parameter --- src/Agent.php | 20 +-------- src/Events/Request/Request.php | 12 ++---- tests/Unit/Events/Request/RequestTest.php | 51 +++++++++++++++++------ 3 files changed, 45 insertions(+), 38 deletions(-) diff --git a/src/Agent.php b/src/Agent.php index 8d061931..05a1b145 100644 --- a/src/Agent.php +++ b/src/Agent.php @@ -48,36 +48,20 @@ final class Agent implements ScoutApmAgent /** @var Config */ private $config; - /** @var Request|null */ private $request; - /** @var Connector */ private $connector; - /** @var LoggerInterface */ private $logger; - - /** - * Class that helps check incoming http paths vs. the configured ignore list - * - * @var IgnoredEndpoints - */ + /** @var IgnoredEndpoints Class that helps check incoming http paths vs. the configured ignore list*/ private $ignoredEndpoints; - - /** - * If this request was marked as ignored - * - * @var bool - */ + /** @var bool If this request was marked as ignored*/ private $isIgnored = false; - /** @var ExtentionCapabilities */ private $phpExtension; - /** @var CacheInterface */ private $cache; - /** @var bool */ private $registered = false; diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index b483fede..a1b477c3 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -17,6 +17,7 @@ use function array_key_exists; use function array_map; use function is_string; +use function microtime; use function strpos; use function substr; @@ -25,19 +26,14 @@ class Request implements CommandWithChildren { /** @var Timer */ private $timer; - /** @var Command[]|array */ private $children = []; - /** @var CommandWithChildren */ private $currentCommand; - /** @var RequestId */ private $id; - /** @var MemoryUsage */ private $startMemory; - /** @var string|null */ private $requestUriOverride; @@ -85,7 +81,7 @@ private function determineRequestPathFromServerGlobal() : string return '/'; } - private function tagRequestIfRequestQueueTimeHeaderExists() : void + private function tagRequestIfRequestQueueTimeHeaderExists(float $currentTimeInSeconds) : void { $headers = FetchRequestHeaders::fromServerGlobal(); @@ -120,14 +116,14 @@ public function stopIfRunning() : void $this->stop(); } - public function stop(?float $overrideTimestamp = null) : void + public function stop(?float $overrideTimestamp = null, ?float $currentTime = null) : void { $this->timer->stop($overrideTimestamp); $this->tag(Tag::TAG_MEMORY_DELTA, MemoryUsage::record()->usedDifferenceInMegabytes($this->startMemory)); $this->tag(Tag::TAG_REQUEST_PATH, $this->requestUriOverride ?? $this->determineRequestPathFromServerGlobal()); - $this->tagRequestIfRequestQueueTimeHeaderExists(); + $this->tagRequestIfRequestQueueTimeHeaderExists($currentTime ?? microtime(true)); } /** @throws Exception */ diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 87f643fa..06046982 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -14,7 +14,6 @@ use function json_encode; use function next; use function reset; -use function sprintf; use function str_repeat; use function time; @@ -164,10 +163,34 @@ public function testSpansCanBeCounted() : void public function queueTimeRequestHeadersProvider() : array { return [ - ['HTTP_X_REQUEST_START', '%d'], - ['HTTP_X_REQUEST_START', 't=%d'], - ['HTTP_X_QUEUE_START', '%d'], - ['HTTP_X_QUEUE_START', 't=%d'], + 'requestStartMilliseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => '2', + 'currentTimeSeconds' => 0.0, + 'requestStartTimeSeconds' => 0.005, + 'expectedQueueTimeNanoseconds' => 3000000.0, + ], + 'requestStartTEqualsMilliseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => 't=2', + 'currentTimeSeconds' => 0.0, + 'requestStartTimeSeconds' => 0.005, + 'expectedQueueTimeNanoseconds' => 3000000.0, + ], + 'queueStartMilliseconds' => [ + 'headerName' => 'HTTP_X_QUEUE_START', + 'headerValue' => '2', + 'currentTimeSeconds' => 0.0, + 'requestStartTimeSeconds' => 0.005, + 'expectedQueueTimeNanoseconds' => 3000000.0, + ], + 'queueStartTEqualsMilliseconds' => [ + 'headerName' => 'HTTP_X_QUEUE_START', + 'headerValue' => 't=2', + 'currentTimeSeconds' => 0.0, + 'requestStartTimeSeconds' => 0.005, + 'expectedQueueTimeNanoseconds' => 3000000.0, + ], ]; } @@ -176,14 +199,19 @@ public function queueTimeRequestHeadersProvider() : array * * @dataProvider queueTimeRequestHeadersProvider */ - public function testRequestIsTaggedWithQueueTime(string $headerName, string $headerValueFormat) : void - { + public function testRequestIsTaggedWithQueueTime( + string $headerName, + string $headerValue, + float $currentTimeSeconds, + float $requestStartTimeSeconds, + float $expectedQueueTimeNanoseconds + ) : void { // 2 = 2ms after epoch - $_SERVER[$headerName] = sprintf($headerValueFormat, 2); + $_SERVER[$headerName] = $headerValue; // 0.005 = 5ms after epoch - $request = new Request(0.005); - $request->stop(); + $request = new Request($requestStartTimeSeconds); + $request->stop(null, $currentTimeSeconds); $f = $request->jsonSerialize(); @@ -193,8 +221,7 @@ public function testRequestIsTaggedWithQueueTime(string $headerName, string $hea continue; } - // queue time should be 3ms (represented as 3000000 nanoseconds, as a float) - self::assertSame(3000000.0, $command['TagRequest']['value']); + self::assertSame($expectedQueueTimeNanoseconds, $command['TagRequest']['value']); $foundTag = true; } From bf120f0a396629c15e03244b41c617e4f5956e56 Mon Sep 17 00:00:00 2001 From: James Titcumb Date: Tue, 3 Mar 2020 16:40:52 +0000 Subject: [PATCH 6/6] Determine scale of timestamp automatically based on current time --- src/Events/Request/Request.php | 43 ++++++++++++++++++- src/Helper/Timer.php | 29 +++++++------ tests/Unit/Events/Request/RequestTest.php | 51 +++++++++++------------ 3 files changed, 80 insertions(+), 43 deletions(-) diff --git a/src/Events/Request/Request.php b/src/Events/Request/Request.php index a1b477c3..a3e27a66 100644 --- a/src/Events/Request/Request.php +++ b/src/Events/Request/Request.php @@ -4,6 +4,7 @@ namespace Scoutapm\Events\Request; +use DateInterval; use Exception; use Scoutapm\Connector\Command; use Scoutapm\Connector\CommandWithChildren; @@ -81,6 +82,41 @@ private function determineRequestPathFromServerGlobal() : string return '/'; } + /** + * Convert an ambiguous float timestamp that could be in nanoseconds, microseconds, milliseconds, or seconds to + * nanoseconds. Return 0.0 for values in the more than 10 years ago. + * + * @throws Exception + */ + private function convertAmbiguousTimestampToSeconds(float $timestamp, float $currentTimestamp) : float + { + $tenYearsAgo = Timer::utcDateTimeFromFloatTimestamp($currentTimestamp) + ->sub(new DateInterval('P10Y')); + + $cutoffTimestamp = (float) $tenYearsAgo + ->setDate((int) $tenYearsAgo->format('Y'), 1, 1) + ->format('U.u'); + + if ($timestamp > ($cutoffTimestamp * 1000000000.0)) { + return $timestamp / 1000000000; + } + + if ($timestamp > ($cutoffTimestamp * 1000000.0)) { + return $timestamp / 1000000; + } + + if ($timestamp > ($cutoffTimestamp * 1000.0)) { + return $timestamp / 1000.0; + } + + if ($timestamp > $cutoffTimestamp) { + return $timestamp; + } + + return 0.0; + } + + /** @throws Exception */ private function tagRequestIfRequestQueueTimeHeaderExists(float $currentTimeInSeconds) : void { $headers = FetchRequestHeaders::fromServerGlobal(); @@ -96,8 +132,11 @@ private function tagRequestIfRequestQueueTimeHeaderExists(float $currentTimeInSe $headerValue = substr($headerValue, 2); } - // Header comes in as milliseconds, so divide by 1,000 to get value in seconds - $headerValueInSeconds = (float) $headerValue / 1000; + $headerValueInSeconds = $this->convertAmbiguousTimestampToSeconds((float) $headerValue, $currentTimeInSeconds); + + if ($headerValueInSeconds === 0.0) { + continue; + } // Time tags should be in nanoseconds, so multiply seconds by 1e9 (1,000,000,000) $this->tag( diff --git a/src/Helper/Timer.php b/src/Helper/Timer.php index 8291a3eb..ae925dee 100644 --- a/src/Helper/Timer.php +++ b/src/Helper/Timer.php @@ -4,7 +4,7 @@ namespace Scoutapm\Helper; -use DateTime; +use DateTimeImmutable; use DateTimeZone; use function microtime; use function sprintf; @@ -42,6 +42,15 @@ public function stop(?float $override = null) : void $this->stop = $override ?? microtime(true); } + public static function utcDateTimeFromFloatTimestamp(float $timestamp) : DateTimeImmutable + { + return DateTimeImmutable::createFromFormat( + self::MICROTIME_FLOAT_FORMAT, + sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $timestamp), + new DateTimeZone('UTC') + ); + } + /** * Formats the stop time as a timestamp suitable for sending to CoreAgent */ @@ -51,13 +60,8 @@ public function getStop() : ?string return null; } - $timestamp = DateTime::createFromFormat( - self::MICROTIME_FLOAT_FORMAT, - sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $this->stop), - new DateTimeZone('UTC') - ); - - return $timestamp->format(self::FORMAT_FOR_CORE_AGENT); + return self::utcDateTimeFromFloatTimestamp($this->stop) + ->format(self::FORMAT_FOR_CORE_AGENT); } /** @@ -65,13 +69,8 @@ public function getStop() : ?string */ public function getStart() : ?string { - $timestamp = DateTime::createFromFormat( - self::MICROTIME_FLOAT_FORMAT, - sprintf(self::FORMAT_FLOAT_TO_6_DECIMAL_PLACES, $this->start), - new DateTimeZone('UTC') - ); - - return $timestamp->format(self::FORMAT_FOR_CORE_AGENT); + return self::utcDateTimeFromFloatTimestamp($this->start) + ->format(self::FORMAT_FOR_CORE_AGENT); } public function getStartAsMicrotime() : float diff --git a/tests/Unit/Events/Request/RequestTest.php b/tests/Unit/Events/Request/RequestTest.php index 06046982..a1013380 100644 --- a/tests/Unit/Events/Request/RequestTest.php +++ b/tests/Unit/Events/Request/RequestTest.php @@ -14,12 +14,15 @@ use function json_encode; use function next; use function reset; +use function sprintf; use function str_repeat; use function time; /** @covers \Scoutapm\Events\Request\Request */ final class RequestTest extends TestCase { + private const FIXED_POINT_UNIX_EPOCH_SECONDS = 1000000000.0; + public function testCanBeInitialized() : void { $request = new Request(); @@ -165,31 +168,31 @@ public function queueTimeRequestHeadersProvider() : array return [ 'requestStartMilliseconds' => [ 'headerName' => 'HTTP_X_REQUEST_START', - 'headerValue' => '2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'requestStartTEqualsMilliseconds' => [ 'headerName' => 'HTTP_X_REQUEST_START', - 'headerValue' => 't=2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('t=%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'queueStartMilliseconds' => [ 'headerName' => 'HTTP_X_QUEUE_START', - 'headerValue' => '2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), ], 'queueStartTEqualsMilliseconds' => [ 'headerName' => 'HTTP_X_QUEUE_START', - 'headerValue' => 't=2', - 'currentTimeSeconds' => 0.0, - 'requestStartTimeSeconds' => 0.005, - 'expectedQueueTimeNanoseconds' => 3000000.0, + 'headerValue' => sprintf('t=%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2), + ], + 'requestStartSeconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%.3f', self::FIXED_POINT_UNIX_EPOCH_SECONDS + 0.002), + ], + 'requestStartMicroseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000000) + 2000), + ], + 'requestStartNanoseconds' => [ + 'headerName' => 'HTTP_X_REQUEST_START', + 'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000000000) + 2000000), ], ]; } @@ -199,19 +202,14 @@ public function queueTimeRequestHeadersProvider() : array * * @dataProvider queueTimeRequestHeadersProvider */ - public function testRequestIsTaggedWithQueueTime( - string $headerName, - string $headerValue, - float $currentTimeSeconds, - float $requestStartTimeSeconds, - float $expectedQueueTimeNanoseconds - ) : void { + public function testRequestIsTaggedWithQueueTime(string $headerName, string $headerValue) : void + { // 2 = 2ms after epoch $_SERVER[$headerName] = $headerValue; // 0.005 = 5ms after epoch - $request = new Request($requestStartTimeSeconds); - $request->stop(null, $currentTimeSeconds); + $request = new Request(self::FIXED_POINT_UNIX_EPOCH_SECONDS + 0.005); + $request->stop(null, self::FIXED_POINT_UNIX_EPOCH_SECONDS); $f = $request->jsonSerialize(); @@ -221,7 +219,8 @@ public function testRequestIsTaggedWithQueueTime( continue; } - self::assertSame($expectedQueueTimeNanoseconds, $command['TagRequest']['value']); + // float rounding errors, yay! + self::assertSame(3000020, (int) $command['TagRequest']['value']); $foundTag = true; }