From 618a983c83eb2ba94b453e687e09187371ad1494 Mon Sep 17 00:00:00 2001 From: Beniamin Date: Tue, 27 Oct 2020 21:27:05 +0200 Subject: [PATCH] remove global span (#171) * remove global span creation when Tracer is initialized and fix batch exporter not exporting in batches but one by one * use the monotonic clock instead of realtime clock to compute time elapsed - realtime clocks can move backwards * add the NoopSpan. It will be used as the root Span * Use NoopSpan for new traces * Generate a new context if the root span is noop * Remove comments * Inline variable * Must set parent as active span so that span ID is propagated * Revert "Must set parent as active span so that span ID is propagated" as context can't be used as span This reverts commit 985fa5e2c4a1b4b99f9ea15f4589da055652b091. * Load NoopSpan when required * Fixed regression: creating a Tracer with an existing context is now supported again. * Add variable to improve readability * Rename variable for clarity. * fix failing psalm checks and add test for root NoopSpan Co-authored-by: Ben Magee --- Context/Context.php | 2 +- api/Trace/Span.php | 2 +- examples/AlwaysOnJaegerExample.php | 16 +- examples/AlwaysOnZipkinExample.php | 12 +- sdk/Trace/NoopSpan.php | 150 ++++++++++++++++++ sdk/Trace/SpanContext.php | 4 +- .../SpanProcessor/BatchSpanProcessor.php | 13 +- sdk/Trace/Tracer.php | 33 ++-- tests/Sdk/Unit/Trace/NoopSpanTest.php | 125 +++++++++++++++ tests/Sdk/Unit/Trace/SpanOptionsTest.php | 3 + .../SpanProcessor/BatchSpanProcessorTest.php | 17 +- tests/Sdk/Unit/Trace/TracingTest.php | 31 ++-- 12 files changed, 357 insertions(+), 51 deletions(-) create mode 100644 sdk/Trace/NoopSpan.php create mode 100644 tests/Sdk/Unit/Trace/NoopSpanTest.php diff --git a/Context/Context.php b/Context/Context.php index 7930b8764..36e3ee664 100644 --- a/Context/Context.php +++ b/Context/Context.php @@ -40,7 +40,7 @@ class Context * @param mixed|null $value * @param Context|null $parent Reference to the parent object */ - public final function __construct(?ContextKey $key=null, $value=null, $parent=null) + final public function __construct(?ContextKey $key=null, $value=null, $parent=null) { $this->key = $key; $this->value = $value; diff --git a/api/Trace/Span.php b/api/Trace/Span.php index b6a50addc..1fcc9d672 100644 --- a/api/Trace/Span.php +++ b/api/Trace/Span.php @@ -24,7 +24,7 @@ public function getStart(): int; /** * Returns system time clock value (MonotonicClock) when the Span was stopped - * @return int + * @return int|null */ public function getEnd(): ?int; diff --git a/examples/AlwaysOnJaegerExample.php b/examples/AlwaysOnJaegerExample.php index 539511e91..68b3a866e 100644 --- a/examples/AlwaysOnJaegerExample.php +++ b/examples/AlwaysOnJaegerExample.php @@ -8,7 +8,7 @@ use OpenTelemetry\Sdk\Trace\Clock; use OpenTelemetry\Sdk\Trace\Sampler\AlwaysOnSampler; use OpenTelemetry\Sdk\Trace\SamplingResult; -use OpenTelemetry\Sdk\Trace\SpanProcessor\SimpleSpanProcessor; +use OpenTelemetry\Sdk\Trace\SpanProcessor\BatchSpanProcessor; use OpenTelemetry\Sdk\Trace\TracerProvider; use OpenTelemetry\Trace as API; @@ -29,16 +29,20 @@ if (SamplingResult::RECORD_AND_SAMPLED === $samplingResult->getDecision()) { echo 'Starting AlwaysOnJaegerExample'; $tracer = (new TracerProvider()) - ->addSpanProcessor(new SimpleSpanProcessor($exporter)) + ->addSpanProcessor(new BatchSpanProcessor($exporter, Clock::get())) ->getTracer('io.opentelemetry.contrib.php'); - echo PHP_EOL . sprintf('Trace with id %s started ', $tracer->getActiveSpan()->getContext()->getTraceId()); - for ($i = 0; $i < 5; $i++) { // start a span, register some events $timestamp = Clock::get()->timestamp(); - $span = $tracer->startAndActivateSpan('session.generate.span' . time()); - $tracer->setActiveSpan($span); + $span = $tracer->startAndActivateSpan('session.generate.span' . microtime(true)); + + echo sprintf( + PHP_EOL . 'Exporting Trace: %s, Parent: %s, Span: %s', + $span->getContext()->getTraceId(), + $span->getParent() ? $span->getParent()->getSpanId() : 'None', + $span->getContext()->getSpanId() + ); $span->setAttribute('remote_ip', '1.2.3.4') ->setAttribute('country', 'USA'); diff --git a/examples/AlwaysOnZipkinExample.php b/examples/AlwaysOnZipkinExample.php index 99035d797..66fe73305 100644 --- a/examples/AlwaysOnZipkinExample.php +++ b/examples/AlwaysOnZipkinExample.php @@ -32,13 +32,17 @@ ->addSpanProcessor(new SimpleSpanProcessor($zipkinExporter)) ->getTracer('io.opentelemetry.contrib.php'); - echo PHP_EOL . sprintf('Trace with id %s started ', $tracer->getActiveSpan()->getContext()->getTraceId()); - for ($i = 0; $i < 5; $i++) { // start a span, register some events $timestamp = Clock::get()->timestamp(); - $span = $tracer->startAndActivateSpan('session.generate.span.' . time()); - $tracer->setActiveSpan($span); + $span = $tracer->startAndActivateSpan('session.generate.span.' . microtime(true)); + + echo sprintf( + PHP_EOL . 'Exporting Trace: %s, Parent: %s, Span: %s', + $span->getContext()->getTraceId(), + $span->getParent() ? $span->getParent()->getSpanId() : 'None', + $span->getContext()->getSpanId() + ); $span->setAttribute('remote_ip', '1.2.3.4') ->setAttribute('country', 'USA'); diff --git a/sdk/Trace/NoopSpan.php b/sdk/Trace/NoopSpan.php new file mode 100644 index 000000000..72ab47404 --- /dev/null +++ b/sdk/Trace/NoopSpan.php @@ -0,0 +1,150 @@ +context = new SpanContext( + SpanContext::INVALID_TRACE, + SpanContext::INVALID_SPAN, + 0, + [] + ); + + $this->attributes = new Attributes(); + $this->events = new Events(); + $this->status = SpanStatus::ok(); + } + + public function getSpanName(): string + { + return ''; + } + + public function getContext(): API\SpanContext + { + return $this->context; + } + + public function getParent(): ?API\SpanContext + { + return null; + } + + public function getStartEpochTimestamp(): int + { + return 0; + } + + public function getStart(): int + { + return 0; + } + + public function getEnd(): ?int + { + return 0; + } + + public function getAttributes(): API\Attributes + { + return $this->attributes; + } + + public function getLinks(): API\Links + { + return $this->links; + } + + public function getEvents(): API\Events + { + return $this->events; + } + + public function getStatus(): API\SpanStatus + { + return $this->status; + } + + public function setAttribute(string $key, $value): API\Span + { + return $this; + } + + public function addEvent(string $name, int $timestamp, ?API\Attributes $attributes = null): API\Span + { + return $this; + } + + public function addLink(API\SpanContext $context, ?API\Attributes $attributes = null): API\Span + { + return $this; + } + + public function updateName(string $name): API\Span + { + return $this; + } + + public function setSpanStatus(string $code, ?string $description = null): API\Span + { + return $this; + } + + public function end(int $timestamp = null): API\Span + { + return $this; + } + + public function isRecording(): bool + { + return false; + } + + public function isSampled(): bool + { + return false; + } + + public function getSpanKind(): int + { + return API\SpanKind::KIND_INTERNAL; + } + + public function getCanonicalStatusCode(): string + { + return $this->status->getCanonicalStatusCode(); + } + + public function getStatusDescription(): string + { + return $this->status->getStatusDescription(); + } + + public function isStatusOk(): bool + { + return $this->status->isStatusOK(); + } +} diff --git a/sdk/Trace/SpanContext.php b/sdk/Trace/SpanContext.php index d61f49bcd..84c4845da 100644 --- a/sdk/Trace/SpanContext.php +++ b/sdk/Trace/SpanContext.php @@ -9,9 +9,9 @@ final class SpanContext implements API\SpanContext { - private const INVALID_TRACE = '00000000000000000000000000000000'; + public const INVALID_TRACE = '00000000000000000000000000000000'; private const VALID_TRACE = '/^[0-9a-f]{32}$/'; - private const INVALID_SPAN = '0000000000000000'; + public const INVALID_SPAN = '0000000000000000'; private const VALID_SPAN = '/^[0-9a-f]{16}$/'; private const SAMPLED_FLAG = 1; diff --git a/sdk/Trace/SpanProcessor/BatchSpanProcessor.php b/sdk/Trace/SpanProcessor/BatchSpanProcessor.php index a88608365..393a77a04 100644 --- a/sdk/Trace/SpanProcessor/BatchSpanProcessor.php +++ b/sdk/Trace/SpanProcessor/BatchSpanProcessor.php @@ -41,7 +41,7 @@ class BatchSpanProcessor implements SpanProcessor /** * @var int */ - private $lastExportTimestamp = 0; + private $lastExportTimestamp; /** * @var Clock */ @@ -107,7 +107,7 @@ public function onEnd(API\Span $span): void */ public function forceFlush(): void { - if (null !== $this->exporter && $this->running) { + if (null !== $this->exporter) { $this->exporter->export($this->queue); $this->queue = []; $this->lastExportTimestamp = $this->clock->timestamp(); @@ -126,7 +126,14 @@ protected function queueReachedLimit(): bool protected function enoughTimeHasPassed(): bool { - $now = $this->clock->timestamp(); + $now = (int) ($this->clock->now() / 1e6); + + // if lastExport never occurred let it start from now on + if (null === $this->lastExportTimestamp) { + $this->lastExportTimestamp = $now; + + return false; + } return $this->scheduledDelayMillis < ($now - $this->lastExportTimestamp); } diff --git a/sdk/Trace/Tracer.php b/sdk/Trace/Tracer.php index 2abfc78b8..850e89187 100644 --- a/sdk/Trace/Tracer.php +++ b/sdk/Trace/Tracer.php @@ -13,15 +13,12 @@ class Tracer implements API\Tracer private $spans = []; private $tail = []; - /** - * @var TracerProvider - */ + /** @var TracerProvider */ private $provider; - - /** - * @var ResourceInfo - */ + /** @var ResourceInfo */ private $resource; + /** @var API\SpanContext|null */ + private $importedContext; public function __construct( TracerProvider $provider, @@ -30,22 +27,16 @@ public function __construct( ) { $this->provider = $provider; $this->resource = $resource; - $context = $context ?: SpanContext::generate(); - - // todo: hold up, why do we automatically make a root Span? - $this->active = $this->generateSpanInstance('tracer', $context); + $this->importedContext = $context; } - /** - * @return Span - */ public function getActiveSpan(): API\Span { while (count($this->tail) && $this->active->getEnd()) { $this->active = array_pop($this->tail); } - return $this->active; + return $this->active ?? new NoopSpan(); } public function setActiveSpan(API\Span $span): void @@ -129,8 +120,14 @@ public function startAndActivateSpanFromContext(string $name, SpanContext $paren */ public function startAndActivateSpan(string $name): API\Span { - $parent = $this->getActiveSpan()->getContext(); - $context = SpanContext::fork($parent->getTraceId(), $parent->isSampled()); + $parentContext = $this->getActiveSpan()->getContext(); + $parentContextIsNoopSpan = !$parentContext->isValidContext(); + + if ($parentContextIsNoopSpan) { + $parentContext = $this->importedContext ?? SpanContext::generate(true); + } + + $context = SpanContext::fork($parentContext->getTraceId(), $parentContext->isSampled()); $span = $this->generateSpanInstance($name, $context); if ($span->isRecording()) { @@ -141,6 +138,7 @@ public function startAndActivateSpan(string $name): API\Span return $this->active; } + public function getSpans(): array { return $this->spans; @@ -166,6 +164,7 @@ private function generateSpanInstance(string $name, API\SpanContext $context): S if ($this->active) { $parent = $this->getActiveSpan()->getContext(); } + $span = new Span($name, $context, $parent); $this->spans[] = $span; diff --git a/tests/Sdk/Unit/Trace/NoopSpanTest.php b/tests/Sdk/Unit/Trace/NoopSpanTest.php new file mode 100644 index 000000000..35a153de7 --- /dev/null +++ b/tests/Sdk/Unit/Trace/NoopSpanTest.php @@ -0,0 +1,125 @@ +span = new NoopSpan(); + } + + /** @test */ + public function itShouldNotHaveANameEvenWhenNameIsUpdated() + { + $this->assertEmpty($this->span->getSpanName()); + + $this->span->updateName('some-custom-name'); + + $this->assertEmpty($this->span->getSpanName()); + } + + /** @test */ + public function attributesCollectionShouldBeEmptyEvenAfterUpdate() + { + $this->assertEmpty($this->span->getAttributes()); + + $this->span->setAttribute('key', 'value'); + $this->assertEmpty($this->span->getAttributes()); + } + + /** @test */ + public function eventsCollectionShouldBeEmptyEvenAfterUpdate() + { + $this->assertEmpty($this->span->getEvents()); + + $this->span->addEvent('event', (Clock::get())->timestamp()); + $this->assertEmpty($this->span->getEvents()); + } + + /** @test */ + public function itsStatusShouldBeOkAndNoUpdatesShouldChangeIt() + { + $this->assertEquals( + SpanStatus::ok(), + $this->span->getStatus() + ); + + $this->assertTrue($this->span->isStatusOk()); + + $this->assertEquals( + SpanStatus::ok()->getStatusDescription(), + $this->span->getStatusDescription() + ); + + $this->assertEquals( + SpanStatus::ok()->getCanonicalStatusCode(), + $this->span->getCanonicalStatusCode() + ); + + $this->span->setSpanStatus(\OpenTelemetry\Trace\SpanStatus::ABORTED); + + $this->assertEquals( + SpanStatus::ok(), + $this->span->getStatus() + ); + + $this->assertTrue($this->span->isStatusOk()); + } + + /** @test */ + public function itsSpanKindShouldBeInternal() + { + $this->assertEquals(SpanKind::KIND_INTERNAL, $this->span->getSpanKind()); + } + + /** @test */ + public function itShouldNeverRecord() + { + $this->assertFalse($this->span->isRecording()); + } + + /** @test */ + public function itShouldNeverBeSampled() + { + $this->assertFalse($this->span->isSampled()); + } + + /** @test */ + public function itShouldNotHaveAParent() + { + $this->assertNull($this->span->getParent()); + } + + /** @test */ + public function itShouldHaveAnInvalidSpanContext() + { + $this->assertFalse($this->span->getContext()->isValidContext()); + } + + /** @test */ + public function itShouldNotBeTimeBounded() + { + $this->assertEmpty($this->span->getStart()); + $this->assertEmpty($this->span->getEnd()); + $this->assertEmpty($this->span->getStartEpochTimestamp()); + + $this->span->end((Clock::get())->timestamp()); + + $this->assertEmpty($this->span->getEnd()); + } +} diff --git a/tests/Sdk/Unit/Trace/SpanOptionsTest.php b/tests/Sdk/Unit/Trace/SpanOptionsTest.php index cd1b270d6..8edd2ce55 100644 --- a/tests/Sdk/Unit/Trace/SpanOptionsTest.php +++ b/tests/Sdk/Unit/Trace/SpanOptionsTest.php @@ -17,6 +17,7 @@ class SpanOptionsTest extends TestCase public function testShouldCreateSpanFromOptions() { $tracer = $this->getTracer(); + $tracer->startAndActivateSpan('firstSpan'); $spanOptions = new SpanOptions($tracer, 'web'); $global = $tracer->getActiveSpan(); @@ -39,6 +40,7 @@ public function testShouldCreateSpanFromOptions() public function testShouldCreateAndSetActiveSpanFromOptions() { $tracer = $this->getTracer(); + $tracer->startAndActivateSpan('firstSpan'); $spanOptions = new SpanOptions($tracer, 'web'); $tracer->getActiveSpan(); $this->assertSame($spanOptions, $spanOptions->setSpanName('web2')); @@ -57,6 +59,7 @@ public function testShouldCreateAndSetActiveSpanFromOptions() public function testShouldCreateCorrectSpanAttributes() { $tracer = $this->getTracer(); + $tracer->startAndActivateSpan('firstSpan'); $spanOptions = new SpanOptions($tracer, 'web'); $tracer->getActiveSpan(); diff --git a/tests/Sdk/Unit/Trace/SpanProcessor/BatchSpanProcessorTest.php b/tests/Sdk/Unit/Trace/SpanProcessor/BatchSpanProcessorTest.php index 9727f6466..fce8eb195 100644 --- a/tests/Sdk/Unit/Trace/SpanProcessor/BatchSpanProcessorTest.php +++ b/tests/Sdk/Unit/Trace/SpanProcessor/BatchSpanProcessorTest.php @@ -28,12 +28,11 @@ public function shouldExportIfBatchLimitIsReachedButDelayNotReached() } $exporter = self::createMock(Exporter::class); - $exporter->expects($this->at(0))->method('export')->with($spans); $exporter->expects($this->atLeastOnce())->method('export'); // Export will still happen even if clock will never trigger the batch $clock = self::createMock(Clock::class); - $clock->method('timestamp')->will($this->returnValue(($exportDelay - 1))); + $clock->method('now')->will($this->returnValue(($exportDelay - 1))); /** @var \OpenTelemetry\Sdk\Trace\Span[] $spans */ /** @var \OpenTelemetry\Sdk\Trace\Exporter $exporter */ @@ -64,17 +63,21 @@ public function shouldExportIfDelayLimitReachedButBatchSizeNotReached() // The clock will be "before" the delay until the final call, then the timeout will trigger $clock = self::createMock(Clock::class); + $timestampReturns = []; for ($i = 0; $i < count($spans) - 1; $i++) { - $timestampReturns[] = $exportDelay - 1; + $timestampReturns[] = ($exportDelay - 1) * 1e6; } - $timestampReturns[count($spans) - 1] = $exportDelay + 1; + $timestampReturns[count($spans) - 1] = ($exportDelay + 1) * 1e6; // forceFlush method will call timestamp once again to set exportedTimestamp - $timestampReturns[count($spans)] = $exportDelay - 1; + $timestampReturns[count($spans)] = ($exportDelay - 1) * 1e6; + $clock - ->method('timestamp') - ->willReturnOnConsecutiveCalls(...$timestampReturns); + ->method('now') + ->willReturnOnConsecutiveCalls(...array_map(function ($e) { + return (int) $e; + }, $timestampReturns)); /** @var \OpenTelemetry\Sdk\Trace\Exporter $exporter */ /** @var \OpenTelemetry\Sdk\Trace\Clock $clock */ diff --git a/tests/Sdk/Unit/Trace/TracingTest.php b/tests/Sdk/Unit/Trace/TracingTest.php index 85c311e62..edfe8a904 100644 --- a/tests/Sdk/Unit/Trace/TracingTest.php +++ b/tests/Sdk/Unit/Trace/TracingTest.php @@ -37,12 +37,17 @@ public function testTracerSpanContextRestore() { $tracerProvider = new SDK\TracerProvider(); $tracer = new Tracer($tracerProvider, ResourceInfo::create(new Attributes([]))); + $tracer->startAndActivateSpan('tracer1.firstSpan'); $spanContext = $tracer->getActiveSpan()->getContext(); $spanContext2 = SpanContext::restore($spanContext->getTraceId(), $spanContext->getSpanId()); $tracer2 = new Tracer($tracerProvider, ResourceInfo::create(new Attributes([])), $spanContext2); + $tracer2->startAndActivateSpan('tracer2.firstSpan'); - $this->assertSame($tracer->getActiveSpan()->getContext()->getTraceId(), $tracer2->getActiveSpan()->getContext()->getTraceId()); + $this->assertSame( + $tracer->getActiveSpan()->getContext()->getTraceId(), + $tracer2->getActiveSpan()->getContext()->getTraceId() + ); } public function testSpanNameUpdate() @@ -72,13 +77,14 @@ public function testNestedSpans() $this->assertEquals($procedure->getParent(), $connection->getContext()); $this->assertEquals($policy->getParent(), $guard->getContext()); - $this->assertCount(5, $tracer->getSpans()); + $this->assertCount(4, $tracer->getSpans()); } public function testCreateSpan() { $tracerProvider = new SDK\TracerProvider(); $tracer = $tracerProvider->getTracer('OpenTelemetry.TracingTest'); + $tracer->startAndActivateSpan('firstSpan'); $global = $tracer->getActiveSpan(); $mysql = $tracer->startAndActivateSpan('mysql'); @@ -103,11 +109,6 @@ public function testCreateSpan() // active span rolled back $this->assertSame($tracer->getActiveSpan(), $global); - - // active span should be kept for global span - $global->end(); - $this->assertSame($tracer->getActiveSpan(), $global); - self::assertTrue($global->isStatusOK()); } public function testStatusManipulation() @@ -121,9 +122,7 @@ public function testStatusManipulation() self::assertFalse($cancelled->isStatusOK()); self::assertSame(SpanStatus::CANCELLED, $cancelled->getCanonicalStatusCode()); self::assertSame(SpanStatus::DESCRIPTION[SpanStatus::CANCELLED], $cancelled->getStatusDescription()); - - // todo: hold up, _two_? - self::assertCount(2, $tracer->getSpans()); + self::assertCount(1, $tracer->getSpans()); } public function testSetSpanStatusWhenNotRecording() @@ -143,6 +142,7 @@ public function testSpanAttributesApi() { $tracerProvider = new SDK\TracerProvider(); $tracer = $tracerProvider->getTracer('OpenTelemetry.TracingTest'); + $tracer->startAndActivateSpan('firstSpan'); /** * @var SDK\Span */ @@ -285,10 +285,21 @@ public function testParentSpanContext() { $tracerProvider = new SDK\TracerProvider(); $tracer = $tracerProvider->getTracer('OpenTelemetry.TracingTest'); + $tracer->startAndActivateSpan('firstSpan'); $global = $tracer->getActiveSpan(); $request = $tracer->startAndActivateSpan('request'); $this->assertSame($request->getParent()->getSpanId(), $global->getContext()->getSpanId()); $this->assertNull($global->getParent()); $this->assertNotNull($request->getParent()); } + + public function testActiveRootSpanIsNoopSpanIfNoParentProvided() + { + $tracer = (new SDK\TracerProvider())->getTracer('OpenTelemetry.TracingTest'); + + $this->assertInstanceOf( + SDK\NoopSpan::class, + $tracer->getActiveSpan() + ); + } }