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.
jonahgeorge · Sep 18, 2018 · 857606a · 857606a
1 parent 8c955f8
commit 857606a
Show file tree

Hide file tree

Showing 2 changed files with 152 additions and 16 deletions.
diff --git 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
@@ -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([]);
+    }
 }