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

perf(opentelemetry): Bucket spans for cleanup #14154

Merged
merged 9 commits into from
Nov 27, 2024
Merged
Show file tree
Hide file tree
Changes from 1 commit
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
Prev Previous commit
Next Next commit
Fix tests
  • Loading branch information
lforst committed Nov 12, 2024
commit c807a308be8c58b34fcf71a45dfe028687909345
25 changes: 17 additions & 8 deletions packages/node/test/integration/transactions.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -595,8 +595,14 @@ describe('Integration | Transactions', () => {

jest.advanceTimersByTime(1);

// Child-spans have been added to the exporter, but they are pending since they are waiting for their parant
expect(exporter['_finishedSpans'].length).toBe(2);
// Child-spans have been added to the exporter, but they are pending since they are waiting for their parent
const finishedSpans1 = [];
exporter['_finishedSpanBuckets'].forEach((bucket: any) => {
if (bucket) {
finishedSpans1.push(...bucket.spans);
}
});
expect(finishedSpans1.length).toBe(2);
expect(beforeSendTransaction).toHaveBeenCalledTimes(0);

// Now wait for 5 mins
Expand All @@ -608,18 +614,21 @@ describe('Integration | Transactions', () => {
jest.advanceTimersByTime(1);

// Old spans have been cleared away
expect(exporter['_finishedSpans'].length).toBe(0);
const finishedSpans2 = [];
exporter['_finishedSpanBuckets'].forEach((bucket: any) => {
if (bucket) {
finishedSpans2.push(...bucket.spans);
}
});
expect(finishedSpans2.length).toBe(0);

// Called once for the 'other span'
expect(beforeSendTransaction).toHaveBeenCalledTimes(1);

expect(logs).toEqual(
expect.arrayContaining([
'SpanExporter has 1 unsent spans remaining',
'SpanExporter has 2 unsent spans remaining',
'SpanExporter exported 1 spans, 2 unsent spans remaining',
`SpanExporter dropping span inner span 1 (${innerSpan1Id}) because it is pending for more than 5 minutes.`,
`SpanExporter dropping span inner span 2 (${innerSpan2Id}) because it is pending for more than 5 minutes.`,
'SpanExporter dropped 2 spans because they were pending for more than 300 seconds.',
'SpanExporter exported 1 spans, 0 unsent spans remaining',
]),
);
});
Expand Down
13 changes: 12 additions & 1 deletion packages/opentelemetry/src/spanExporter.ts
Original file line number Diff line number Diff line change
Expand Up @@ -66,11 +66,19 @@ export class SentrySpanExporter {
const currentTimestampInS = Math.floor(Date.now() / 1000);

if (this._lastCleanupTimestampInS !== currentTimestampInS) {
let droppedSpanCount = 0;
this._finishedSpanBuckets.forEach((bucket, i) => {
if (bucket && bucket.timestampInS <= currentTimestampInS - this._finishedSpanBucketSize) {
droppedSpanCount += bucket.spans.size;
this._finishedSpanBuckets[i] = undefined;
}
});
if (droppedSpanCount > 0) {
DEBUG_BUILD &&
logger.log(
`SpanExporter dropped ${droppedSpanCount} spans because they were pending for more than ${this._finishedSpanBucketSize} seconds.`,
);
}
this._lastCleanupTimestampInS = currentTimestampInS;
}

Expand Down Expand Up @@ -110,7 +118,10 @@ export class SentrySpanExporter {

const sentSpanCount = sentSpans.size;

DEBUG_BUILD && logger.log(`SpanExporter exported ${sentSpanCount} spans`);
const remainingOpenSpanCount = finishedSpans.length - sentSpanCount;

DEBUG_BUILD &&
logger.log(`SpanExporter exported ${sentSpanCount} spans, ${remainingOpenSpanCount} unsent spans remaining`);

sentSpans.forEach(span => {
const bucketEntry = this._spansToBucketEntry.get(span);
Expand Down
55 changes: 34 additions & 21 deletions packages/opentelemetry/test/integration/transactions.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -460,24 +460,22 @@ describe('Integration | Transactions', () => {
throw new Error('No exporter found, aborting test...');
}

let innerSpan1Id: string | undefined;
let innerSpan2Id: string | undefined;

void startSpan({ name: 'test name' }, async () => {
const subSpan = startInactiveSpan({ name: 'inner span 1' });
innerSpan1Id = subSpan.spanContext().spanId;
subSpan.end();

startSpan({ name: 'inner span 2' }, innerSpan => {
innerSpan2Id = innerSpan.spanContext().spanId;
});
startInactiveSpan({ name: 'inner span 1' }).end();
startInactiveSpan({ name: 'inner span 2' }).end();

// Pretend this is pending for 10 minutes
await new Promise(resolve => setTimeout(resolve, 10 * 60 * 1000));
});

// Child-spans have been added to the exporter, but they are pending since they are waiting for their parant
expect(exporter['_finishedSpans'].length).toBe(2);
// Child-spans have been added to the exporter, but they are pending since they are waiting for their parent
const finishedSpans1 = [];
exporter['_finishedSpanBuckets'].forEach(bucket => {
if (bucket) {
finishedSpans1.push(...bucket.spans);
}
});
expect(finishedSpans1.length).toBe(2);
expect(beforeSendTransaction).toHaveBeenCalledTimes(0);

// Now wait for 5 mins
Expand All @@ -489,18 +487,21 @@ describe('Integration | Transactions', () => {
jest.advanceTimersByTime(1);

// Old spans have been cleared away
expect(exporter['_finishedSpans'].length).toBe(0);
const finishedSpans2 = [];
exporter['_finishedSpanBuckets'].forEach(bucket => {
if (bucket) {
finishedSpans2.push(...bucket.spans);
}
});
expect(finishedSpans2.length).toBe(0);

// Called once for the 'other span'
expect(beforeSendTransaction).toHaveBeenCalledTimes(1);

expect(logs).toEqual(
expect.arrayContaining([
'SpanExporter has 1 unsent spans remaining',
'SpanExporter has 2 unsent spans remaining',
'SpanExporter exported 1 spans, 2 unsent spans remaining',
`SpanExporter dropping span inner span 1 (${innerSpan1Id}) because it is pending for more than 5 minutes.`,
`SpanExporter dropping span inner span 2 (${innerSpan2Id}) because it is pending for more than 5 minutes.`,
'SpanExporter dropped 2 spans because they were pending for more than 300 seconds.',
'SpanExporter exported 1 spans, 0 unsent spans remaining',
]),
);
});
Expand Down Expand Up @@ -553,7 +554,13 @@ describe('Integration | Transactions', () => {
expect(transactions[0]?.spans).toHaveLength(2);

// No spans are pending
expect(exporter['_finishedSpans'].length).toBe(0);
const finishedSpans = [];
exporter['_finishedSpanBuckets'].forEach(bucket => {
if (bucket) {
finishedSpans.push(...bucket.spans);
}
});
expect(finishedSpans.length).toBe(0);
});

it('discards child spans that are finished after their parent span', async () => {
Expand Down Expand Up @@ -607,8 +614,14 @@ describe('Integration | Transactions', () => {
expect(transactions[0]?.spans).toHaveLength(1);

// subSpan2 is pending (and will eventually be cleaned up)
expect(exporter['_finishedSpans'].length).toBe(1);
expect(exporter['_finishedSpans'][0]?.name).toBe('inner span 2');
const finishedSpans: any = [];
exporter['_finishedSpanBuckets'].forEach(bucket => {
if (bucket) {
finishedSpans.push(...bucket.spans);
}
});
expect(finishedSpans.length).toBe(1);
expect(finishedSpans[0]?.name).toBe('inner span 2');
});

it('uses & inherits DSC on span trace state', async () => {
Expand Down