Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Capture request queue time #149

Merged
merged 6 commits into from
Dec 20, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
18 changes: 18 additions & 0 deletions src/Events/Request/Request.php
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
Expand Down Expand Up @@ -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) {
Expand All @@ -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 */
Expand Down
1 change: 1 addition & 0 deletions src/Events/Tag/Tag.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
71 changes: 71 additions & 0 deletions src/Helper/FetchRequestHeaders.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,71 @@
<?php

declare(strict_types=1);

namespace Scoutapm\Helper;

use const ARRAY_FILTER_USE_BOTH;
use function array_combine;
use function array_filter;
use function array_keys;
use function array_map;
use function is_string;
use function str_replace;
use function strpos;
use function strtolower;
use function substr;
use function ucwords;

abstract class FetchRequestHeaders
{
/** @return array<string, string> */
public static function fromServerGlobal() : array
{
return self::fromArray($_SERVER);
}

/**
* @param array<int|string, string> $server
*
* @return array<string, string>
*/
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<int|string, string> $server
*
* @return array<string, string>
*
* @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
);
}
}
5 changes: 5 additions & 0 deletions src/Helper/Timer.php
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*/
Expand Down
27 changes: 27 additions & 0 deletions tests/Unit/Events/Request/RequestTest.php
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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']);
}
}
43 changes: 43 additions & 0 deletions tests/Unit/Helper/FetchRequestHeadersTest.php
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
<?php

declare(strict_types=1);

namespace Scoutapm\UnitTests\Helper;

use PHPUnit\Framework\TestCase;
use Scoutapm\Helper\FetchRequestHeaders;

/** @covers \Scoutapm\Helper\FetchRequestHeaders */
final class FetchRequestHeadersTest extends TestCase
{
public function testFromArray() : void
{
$oldServer = $_SERVER;
$_SERVER = [
'SCRIPT_NAME' => $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;
}
}
1 change: 1 addition & 0 deletions tests/Unit/Helper/TimerTest.php
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ public function testCreatingTheTimerSetsStartTime() : void
{
$timer = new Timer();
self::assertNotNull($timer->getStart());
self::assertIsFloat($timer->getStartAsMicrotime());
}

public function testStoppingSetsStopTime() : void
Expand Down