From 857606a70341bd12ef6f779f1276fbdb2ab4e20b Mon Sep 17 00:00:00 2001 From: Fredi Pevcin Date: Tue, 18 Sep 2018 19:37:16 +0200 Subject: [PATCH] UPD [span] Convert startTime/endTime to the same unit (#67) When setting the start/end time as DateTime, the duration was negative as it was not able to extract correct timestamp. --- src/Jaeger/Span.php | 51 ++++++++++++----- tests/Jaeger/SpanTest.php | 117 +++++++++++++++++++++++++++++++++++++- 2 files changed, 152 insertions(+), 16 deletions(-) diff --git a/src/Jaeger/Span.php b/src/Jaeger/Span.php index 9059722..8c2e05c 100644 --- a/src/Jaeger/Span.php +++ b/src/Jaeger/Span.php @@ -93,7 +93,7 @@ public function __construct( $this->tracer = $tracer; $this->operationName = $operationName; - $this->startTime = $startTime ?? $this->timestampMicro(); + $this->startTime = $this->microTime($startTime); $this->endTime = null; $this->kind = null; $this->peer = null; @@ -104,6 +104,38 @@ public function __construct( } } + /** + * Converts time to microtime int + * - int represents microseconds + * - float represents seconds + * + * @param int|float|DateTime|null $time + * @return int + */ + protected function microTime($time): int + { + if ($time === null) { + return $this->timestampMicro(); + } + + if ($time instanceof \DateTimeInterface) { + return (int)round($time->format('U.u') * 1000000, 0); + } + + if (is_int($time)) { + return $time; + } + + if (is_float($time)) { + return (int)round($time * 1000000, 0); + } + + throw new \InvalidArgumentException(sprintf( + 'Time should be one of the types int|float|DateTime|null, got %s.', + gettype($time) + )); + } + /** * @return Tracer */ @@ -121,15 +153,15 @@ public function isDebug(): bool } /** - * @return DateTime|float|int|null + * @return int */ - public function getStartTime() + public function getStartTime(): int { return $this->startTime; } /** - * @return DateTime|float|int|null + * @return int|null */ public function getEndTime() { @@ -176,7 +208,7 @@ public function finish($finishTime = null, array $logRecords = []) $this->log($logRecord); } - $this->endTime = $finishTime ?? $this->timestampMicro(); + $this->endTime = $this->microTime($finishTime); $this->tracer->reportSpan($this); } @@ -331,14 +363,7 @@ public function isRpcClient(): bool */ public function log(array $fields = [], $timestamp = null) { - if ($timestamp instanceof \DateTimeInterface || $timestamp instanceof \DateTime) { - $timestamp = $timestamp->getTimestamp(); - } - - if ($timestamp !== null) { - $timestamp = (int) ($timestamp * 1000000); - } - + $timestamp = $this->microTime($timestamp); if ($timestamp < $this->getStartTime()) { $timestamp = $this->timestampMicro(); } diff --git a/tests/Jaeger/SpanTest.php b/tests/Jaeger/SpanTest.php index ed91e26..b11feda 100644 --- a/tests/Jaeger/SpanTest.php +++ b/tests/Jaeger/SpanTest.php @@ -31,6 +31,15 @@ public function setUp() $this->context = new SpanContext(0, 0,0, SAMPLED_FLAG); } + /** + * {@inheritdoc} + */ + protected function tearDown() + { + $this->tracer = null; + $this->context = null; + } + /** @test */ public function shouldProperlyInitializeAtConstructTime() { @@ -112,7 +121,7 @@ public function shouldAddLogRecordsToTheSpan() $dateTime03 = microtime(true) + 5; $span->log($fields01, $dateTime01); - $span->log($fields02, $dateTime01->getTimestamp()); + $span->log($fields02, $dateTime01->getTimestamp()*1000000); $span->log($fields02, $dateTime03); $span->log($fields02); @@ -121,11 +130,11 @@ public function shouldAddLogRecordsToTheSpan() $this->assertCount(4, $logs); $this->assertInternalType('integer', $logs[0]['timestamp']); - $this->assertSame($dateTime01->getTimestamp() * 1000000, $logs[0]['timestamp']); + $this->assertEquals((int)($dateTime01->format('U.u')*1000000), $logs[0]['timestamp']); $this->assertSame($fields01, $logs[0]['fields']); $this->assertInternalType('integer', $logs[1]['timestamp']); - $this->assertSame($dateTime02 * 1000000, $logs[1]['timestamp']); + $this->assertSame($dateTime02*1000000, $logs[1]['timestamp']); $this->assertSame($fields02, $logs[1]['fields']); $this->assertInternalType('integer', $logs[2]['timestamp']); @@ -135,4 +144,106 @@ public function shouldAddLogRecordsToTheSpan() $this->assertInternalType('integer', $logs[3]['timestamp']); $this->assertSame($fields02, $logs[3]['fields']); } + + /** @test */ + public function timingDefaultTimes() + { + $span = new Span($this->context, $this->tracer, 'test-operation'); + $span->finish(); + + $this->assertEquals(0.0, round(($span->getEndTime() - $span->getStartTime()) / 1000000)); + } + + /** @test */ + public function timingSetStartTimeAsDateTime() + { + $span = new Span($this->context, $this->tracer, 'test-operation', [], new \DateTime('-2 seconds')); + $span->finish(); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetEndTimeAsDateTime() + { + $span = new Span($this->context, $this->tracer, 'test-operation'); + + $endTime = new \DateTime('+2 seconds'); + // add microseconds because php < 7.1 has a bug + // https://bugs.php.net/bug.php?id=48225 + if (version_compare(phpversion(), '7.1', '<')) { + list($usec) = explode(' ', microtime()); + $endTime = \DateTime::createFromFormat('U.u', $endTime->format('U')+$usec); + } + $span->finish($endTime); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetStartTimeAsInt() + { + $span = new Span($this->context, $this->tracer, 'test-operation', [], (int) round((microtime(true) - 2) * 1000000)); + $span->finish(); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetEndTimeAsInt() + { + $span = new Span($this->context, $this->tracer, 'test-operation'); + $span->finish((int) round((microtime(true) + 2) * 1000000)); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetStartTimeAsFloat() + { + $span = new Span($this->context, $this->tracer, 'test-operation', [], microtime(true) - 2); + $span->finish(); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetEndTimeAsFloat() + { + $span = new Span($this->context, $this->tracer, 'test-operation'); + $span->finish(microtime(true) + 2); + + $this->assertSpanDuration($span); + } + + /** @test */ + public function timingSetMixedTimes() + { + $span = new Span($this->context, $this->tracer, 'test-operation', [], new \DateTime()); + $span->finish(microtime(true) + 2); + + $this->assertSpanDuration($span); + } + + protected function assertSpanDuration(Span $span) + { + $this->assertEquals(2, (int)(($span->getEndTime() - $span->getStartTime()) / 1000000)); + } + + /** @test */ + public function invalidStartTime() + { + $this->expectException(\InvalidArgumentException::class); + $this->expectExceptionMessage('Time should be one of the types int|float|DateTime|null, got string.'); + $span = new Span($this->context, $this->tracer, 'test-operation', [], 'string'); + } + + /** @test */ + public function invalidEndTime() + { + $span = new Span($this->context, $this->tracer, 'test-operation'); + $this->expectException(\InvalidArgumentException::class); + $this->expectExceptionMessage('Time should be one of the types int|float|DateTime|null, got array.'); + $span->finish([]); + } }