Merge pull request #169 from scoutapp/fix-queue-time-calculation

Fix queue time calculation
scoutapp · Mar 3, 2020 · 00aab45 · 00aab45
2 parents 8afdcbf + bf120f0
commit 00aab45
Show file tree

Hide file tree

Showing 5 changed files with 130 additions and 53 deletions.
diff --git 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
@@ -4,6 +4,7 @@
 
 namespace Scoutapm\Events\Request;
 
+use DateInterval;
 use Exception;
 use Scoutapm\Connector\Command;
 use Scoutapm\Connector\CommandWithChildren;
@@ -17,34 +18,32 @@
 use function array_key_exists;
 use function array_map;
 use function is_string;
+use function microtime;
+use function strpos;
+use function substr;
 
 /** @internal */
 class Request implements CommandWithChildren
 {
     /** @var Timer */
     private $timer;
-
     /** @var Command[]|array<int, Command> */
     private $children = [];
-
     /** @var CommandWithChildren */
     private $currentCommand;
-
     /** @var RequestId */
     private $id;
-
     /** @var MemoryUsage */
     private $startMemory;
-
     /** @var string|null */
     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;
@@ -83,7 +82,42 @@ private function determineRequestPathFromServerGlobal() : string
         return '/';
     }
 
-    private function tagRequestIfRequestQueueTimeHeaderExists() : void
+    /**
+     * 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();
 
@@ -92,8 +126,23 @@ private function tagRequestIfRequestQueueTimeHeaderExists() : void
                 continue;
             }
 
-            $headerValue = (float) $headers[$headerToCheck] / 10000;
-            $this->tag(Tag::TAG_QUEUE_TIME, ($this->timer->getStartAsMicrotime() - $headerValue) * 1e9);
+            $headerValue = $headers[$headerToCheck];
+
+            if (strpos($headerValue, 't=') === 0) {
+                $headerValue = substr($headerValue, 2);
+            }
+
+            $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(
+                Tag::TAG_QUEUE_TIME,
+                ($this->timer->getStartAsMicrotime() - $headerValueInSeconds) * 1e9
+            );
         }
     }
 
@@ -106,14 +155,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/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,27 +60,17 @@ 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);
     }
 
     /**
      * Formats the stop time as a timestamp suitable for sending to CoreAgent
      */
     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/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
@@ -12,15 +12,17 @@
 use function array_key_exists;
 use function json_decode;
 use function json_encode;
-use function microtime;
 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();
@@ -160,12 +162,54 @@ public function testSpansCanBeCounted() : void
         self::assertSame(2, $request->collectedSpans());
     }
 
-    public function testRequestIsTaggedWithQueueTime() : void
+    /** @return string[][] */
+    public function queueTimeRequestHeadersProvider() : array
     {
-        $_SERVER['HTTP_X_REQUEST_START'] = (string) ((microtime(true) - 2) * 10000);
+        return [
+            'requestStartMilliseconds' => [
+                'headerName' => 'HTTP_X_REQUEST_START',
+                'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2),
+            ],
+            'requestStartTEqualsMilliseconds' => [
+                'headerName' => 'HTTP_X_REQUEST_START',
+                'headerValue' => sprintf('t=%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2),
+            ],
+            'queueStartMilliseconds' => [
+                'headerName' => 'HTTP_X_QUEUE_START',
+                'headerValue' => sprintf('%d', (self::FIXED_POINT_UNIX_EPOCH_SECONDS * 1000) + 2),
+            ],
+            'queueStartTEqualsMilliseconds' => [
+                'headerName' => 'HTTP_X_QUEUE_START',
+                '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),
+            ],
+        ];
+    }
 
-        $request = new Request();
-        $request->stop();
+    /**
+     * @throws Exception
+     *
+     * @dataProvider queueTimeRequestHeadersProvider
+     */
+    public function testRequestIsTaggedWithQueueTime(string $headerName, string $headerValue) : void
+    {
+        // 2 = 2ms after epoch
+        $_SERVER[$headerName] = $headerValue;
+
+        // 0.005 = 5ms after epoch
+        $request = new Request(self::FIXED_POINT_UNIX_EPOCH_SECONDS + 0.005);
+        $request->stop(null, self::FIXED_POINT_UNIX_EPOCH_SECONDS);
 
         $f = $request->jsonSerialize();
 
@@ -175,13 +219,13 @@ public function testRequestIsTaggedWithQueueTime() : void
                 continue;
             }
 
-            self::assertGreaterThanOrEqual(1900000000, $command['TagRequest']['value']);
-            self::assertLessThanOrEqual(2100000000, $command['TagRequest']['value']);
+            // float rounding errors, yay!
+            self::assertSame(3000020, (int) $command['TagRequest']['value']);
             $foundTag = true;
         }
 
         self::assertTrue($foundTag, 'Could not find queue time tag');
 
-        unset($_SERVER['HTTP_X_REQUEST_START']);
+        unset($_SERVER[$headerName]);
     }
 }