From ddb2cf7636339ca3a23e04f94782802392a01b48 Mon Sep 17 00:00:00 2001 From: Marcus Griep Date: Mon, 13 Feb 2023 10:04:57 -0700 Subject: [PATCH 1/2] feat(sdk-trace-base): add diagnostic logging when spans are dropped --- CHANGELOG.md | 1 + .../src/export/BatchSpanProcessorBase.ts | 16 ++++++++++++++++ 2 files changed, 17 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index f1670b19c7..9a2a00a259 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/ * feat(sdk-metrics): apply binary search in histogram recording [#3539](https://github.com/open-telemetry/opentelemetry-js/pull/3539) @legendecas * perf(propagator-jaeger): improve deserializeSpanContext performance [#3541](https://github.com/open-telemetry/opentelemetry-js/pull/3541) @doochik * feat: support TraceState in SamplingResult [#3530](https://github.com/open-telemetry/opentelemetry-js/pull/3530) @raphael-theriault-swi +* feat(sdk-trace-base): add diagnostic logging when spans are dropped [#3610](https://github.com/open-telemetry/opentelemetry-js/pull/3610) @neoeinstein ### :bug: (Bug Fix) diff --git a/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts b/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts index 1a0968642d..42c7ac4965 100644 --- a/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts +++ b/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts @@ -44,6 +44,7 @@ export abstract class BatchSpanProcessorBase private _finishedSpans: ReadableSpan[] = []; private _timer: NodeJS.Timeout | undefined; private _shutdownOnce: BindOnceFuture; + private _droppedSpansCount: number = 0; constructor(private readonly _exporter: SpanExporter, config?: T) { const env = getEnv(); @@ -117,8 +118,23 @@ export abstract class BatchSpanProcessorBase private _addToBuffer(span: ReadableSpan) { if (this._finishedSpans.length >= this._maxQueueSize) { // limit reached, drop span + + if (this._droppedSpansCount === 0) { + diag.debug('maxQueueSize reached, dropping spans'); + } + this._droppedSpansCount++; + return; } + + if (this._droppedSpansCount > 0) { + // some spans were dropped, log once with count of spans dropped + diag.warn( + `Dropped ${this._droppedSpansCount} spans because maxQueueSize reached` + ); + this._droppedSpansCount = 0; + } + this._finishedSpans.push(span); this._maybeStartTimer(); } From f2974ba49cdf7e3fc054b1420c1c6cf694909ec2 Mon Sep 17 00:00:00 2001 From: Marcus Griep Date: Tue, 14 Feb 2023 07:28:15 -0700 Subject: [PATCH 2/2] test(sdk-trace-base): add test for diagnostic logging on dropped spans --- .../export/BatchSpanProcessorBase.test.ts | 34 +++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts index 9149e6cbf8..4c9fcb7ecd 100644 --- a/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts +++ b/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts @@ -440,6 +440,40 @@ describe('BatchSpanProcessorBase', () => { } assert.equal(processor['_finishedSpans'].length, 6); }); + it('should count and report dropped spans', done => { + const debugStub = sinon.spy(diag, 'debug'); + const warnStub = sinon.spy(diag, 'warn'); + const span = createSampledSpan('test'); + for (let i = 0, j = 6; i < j; i++) { + processor.onStart(span, ROOT_CONTEXT); + processor.onEnd(span); + } + assert.equal(processor['_finishedSpans'].length, 6); + assert.equal(processor['_droppedSpansCount'], 0); + sinon.assert.notCalled(debugStub); + + processor.onStart(span, ROOT_CONTEXT); + processor.onEnd(span); + + assert.equal(processor['_finishedSpans'].length, 6); + assert.equal(processor['_droppedSpansCount'], 1); + sinon.assert.calledOnce(debugStub); + + processor.forceFlush().then(() => { + processor.onStart(span, ROOT_CONTEXT); + processor.onEnd(span); + + assert.equal(processor['_finishedSpans'].length, 1); + assert.equal(processor['_droppedSpansCount'], 0); + + sinon.assert.calledOnceWithExactly( + warnStub, + 'Dropped 1 spans because maxQueueSize reached' + ); + + done(); + }); + }); }); });