Skip to content

Commit

Permalink
Determine scale of timestamp automatically based on current time
Browse files Browse the repository at this point in the history
  • Loading branch information
@asgrim
asgrim committed Mar 3, 2020
1 parent 917edb9 commit bf120f0
Show file tree
Hide file tree
Showing 3 changed files with 80 additions and 43 deletions.
43 changes: 41 additions & 2 deletions src/Events/Request/Request.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,7 @@

namespace Scoutapm\Events\Request;

use DateInterval;
use Exception;
use Scoutapm\Connector\Command;
use Scoutapm\Connector\CommandWithChildren;
Expand Down Expand Up @@ -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();
Expand All @@ -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(
Expand Down
29 changes: 14 additions & 15 deletions src/Helper/Timer.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@

namespace Scoutapm\Helper;

use DateTime;
use DateTimeImmutable;
use DateTimeZone;
use function microtime;
use function sprintf;
Expand Down Expand Up @@ -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
*/
Expand All @@ -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
Expand Down
51 changes: 25 additions & 26 deletions tests/Unit/Events/Request/RequestTest.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand Down Expand Up @@ -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),
],
];
}
Expand All @@ -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();

Expand All @@ -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;
}

Expand Down

0 comments on commit bf120f0

Please sign in to comment.