Skip to content

Commit 0d5b587

Browse files
committed
fix(native-spans): send one request per trace chunk again
The previous commit staged every group and sent the whole flush as one multi-trace payload. The native chunk Vec does accumulate, so that works at the protocol level, but it changes what a consumer observes per payload: `traces[0]` is then whichever chunk happened to be staged first, not the only chunk. That broke 19 plugin suites which were green on the parent commit. rhea, for example, reads `traces[0][0]` and got `amqp.send` where it expected `amqp.receive`. The legacy AgentWriter produces one trace per payload at the flush intervals these paths run with, and the test agent plus every `traces[0][0]` assertion depends on that shape. Restore the per-group prepare/send chain, and with it the per-chunk `.requests`/`.responses` and OTLP export counters. Drop the payload-size split in `flush()`: one chunk per request already bounds a payload to a single trace. The `export()` soft limit stays, since it bounds how much is buffered rather than how much one request carries. Keep the reclamation work from the parent commit, which is unaffected: `setAgentUrl` still frees the state it replaces, and rebuilds are still amortized over dropped spans. Batching remains possible and is worth revisiting, but it needs the test agent to become chunk-oriented rather than request-oriented, which is a change to shared infrastructure that 80 spec files depend on.
1 parent cced1e7 commit 0d5b587

4 files changed

Lines changed: 132 additions & 154 deletions

File tree

packages/dd-trace/src/exporters/native/index.js

Lines changed: 26 additions & 47 deletions
Original file line numberDiff line numberDiff line change
@@ -194,20 +194,21 @@ class NativeExporter {
194194
* Mirror the deleted OtlpHttpTraceExporter's per-request telemetry counters.
195195
* No-op on the agent path.
196196
*
197-
* `attempts`/`successes` measure export *pushes*, so they are incremented once
198-
* per HTTP request. The deleted JS exporter's `export()` was invoked per trace
199-
* chunk and issued one request each, so its `spans:` tag was that chunk's span
200-
* count; `flushSpansGrouped` coalesces the whole flush into one multi-chunk
201-
* request, so the equivalent tag is the payload's total span count.
197+
* The deleted JS exporter's `export()` was invoked per trace chunk and issued
198+
* one HTTP request each, tagged with that chunk's span count.
199+
* `flushSpansGrouped` also sends one request per chunk, so emit once per group
200+
* with that group's span count: a single per-flush increment would under-count
201+
* attempts by the number of chunks and would turn `spans:` into an unbounded
202+
* whole-flush total (the telemetry namespace map never evicts keys).
202203
*
203204
* @param {string} metric `otel.traces_export_attempts` or `..._successes`
204205
* @param {Array<{spanIds: Uint8Array[]}>} groups Groups in this flush
205206
*/
206207
#recordOtlpTelemetry (metric, groups) {
207208
if (this.#otlpTelemetryTags === null) return
208-
let spans = 0
209-
for (const group of groups) spans += group.spanIds.length
210-
tracerMetrics.count(metric, [...this.#otlpTelemetryTags, `spans:${spans}`]).inc(1)
209+
for (const group of groups) {
210+
tracerMetrics.count(metric, [...this.#otlpTelemetryTags, `spans:${group.spanIds.length}`]).inc(1)
211+
}
211212
}
212213

213214
/**
@@ -560,36 +561,12 @@ class NativeExporter {
560561
return
561562
}
562563

563-
// One flush is one HTTP request, so cap what a single payload carries. The
564-
// soft-limit trigger in `export()` bounds how much is buffered while idle, but
565-
// it cannot bound this: sends are serialized, so while one is in flight
566-
// `flush()` only records `#flushRequested` and `_pendingSpanChunks` keeps
567-
// growing for the whole round trip. Take whole chunks up to the limit and
568-
// leave the rest for the send `#finishSend` will start immediately after.
569-
let spanChunks
570-
if (this._pendingSpans.length > SOFT_LIMIT_SPANS) {
571-
let taken = 0
572-
let i = 0
573-
// Never split a chunk - chunk boundaries are the processor's trace
574-
// boundaries. Always take at least one, even if it alone exceeds the limit.
575-
while (i < this._pendingSpanChunks.length &&
576-
(taken === 0 || taken + this._pendingSpanChunks[i].length <= SOFT_LIMIT_SPANS)) {
577-
taken += this._pendingSpanChunks[i].length
578-
i++
579-
}
580-
spanChunks = this._pendingSpanChunks.slice(0, i)
581-
this._pendingSpanChunks = this._pendingSpanChunks.slice(i)
582-
// `_pendingSpans` is the in-order concatenation of the chunks, so the
583-
// remainder is exactly the tail past what this payload took.
584-
this._pendingSpans = this._pendingSpans.slice(taken)
585-
// Guarantee the remainder ships right after this send instead of waiting
586-
// out another flushInterval.
587-
this.#flushRequested = true
588-
} else {
589-
spanChunks = this._pendingSpanChunks
590-
this._pendingSpans = []
591-
this._pendingSpanChunks = []
592-
}
564+
// Each chunk becomes its own HTTP request (see flushSpansGrouped), so payload
565+
// size is bounded by one trace and there is nothing to split here. The
566+
// soft-limit trigger in `export()` still bounds how much is buffered.
567+
const spanChunks = this._pendingSpanChunks
568+
this._pendingSpans = []
569+
this._pendingSpanChunks = []
593570

594571
// Convert each SpanProcessor export call into one or more native chunks,
595572
// splitting only traces that happen to share one export call. Never group
@@ -598,11 +575,12 @@ class NativeExporter {
598575
// when flushInterval coalesces HTTP sends.
599576
const groups = this.#groupsFromSpanChunks(spanChunks, true)
600577

601-
// `flushSpansGrouped` stages every chunk synchronously and issues exactly one
602-
// HTTP request for the whole flush, so `.requests`/`.responses` are counted
603-
// once here - the same per-request scale as `.errors` and as the legacy
604-
// AgentWriter's `_sendPayload`.
605-
runtimeMetrics.increment(`${METRIC_PREFIX}.requests`, true)
578+
// `flushSpansGrouped` sends one request per trace chunk, so count per chunk:
579+
// a single per-flush increment reported 1/N of the real request volume and
580+
// left `.requests` on a different scale from `.errors`, which is per-attempt.
581+
for (let i = 0; i < groups.length; i++) {
582+
runtimeMetrics.increment(`${METRIC_PREFIX}.requests`, true)
583+
}
606584
this.#recordOtlpTelemetry('otel.traces_export_attempts', groups)
607585
// Self-guarded (`integrationsAlreadyRan`), so the repeat cost is one boolean.
608586
// Without this the on-by-default `INTEGRATIONS LOADED` startup line never
@@ -619,9 +597,8 @@ class NativeExporter {
619597
this.#firstFlushSent = true
620598
firstFlushChannel.publish()
621599
}
622-
// One request carrying one chunk per trace: `prepareChunk` appends to a
623-
// native chunk Vec and `sendPreparedChunk` drains all of it into a single
624-
// multi-trace payload, which is the shape the legacy AgentWriter sent.
600+
// One request per trace chunk, sequentially, preserving the legacy writer's
601+
// one-trace-per-payload shape that `traces[0]` consumers rely on.
625602
let sendGrouped
626603
try {
627604
sendGrouped = this._nativeSpans.flushSpansGrouped(groups)
@@ -633,7 +610,9 @@ class NativeExporter {
633610
sendGrouped
634611
.then((response) => {
635612
this.#flushInFlight = false
636-
runtimeMetrics.increment(`${METRIC_PREFIX}.responses`, true)
613+
for (let i = 0; i < groups.length; i++) {
614+
runtimeMetrics.increment(`${METRIC_PREFIX}.responses`, true)
615+
}
637616
this.#recordOtlpTelemetry('otel.traces_export_successes', groups)
638617
// The agent's response carries per-service sampling rates. Feed them
639618
// back into the priority sampler so adaptive (agent-driven) sampling

packages/dd-trace/src/native/native_spans.js

Lines changed: 75 additions & 44 deletions
Original file line numberDiff line numberDiff line change
@@ -1209,65 +1209,47 @@ class NativeSpansInterface {
12091209
* local root. Passing many traces as one chunk would lump distinct trace_ids
12101210
* together and stamp only the first — corrupting sampling/grouping under load.
12111211
*
1212-
* `prepareChunk` appends to a native chunk Vec and `sendPreparedChunk` drains
1213-
* all of it into a single multi-trace request (libdatadog-nodejs #159), which
1214-
* is the same shape the legacy writer sends. So stage the whole flush, then
1215-
* send once: one HTTP request per flush carrying one chunk per trace.
1216-
*
1217-
* Staging synchronously also matters for correctness. `prepareChunk` is what
1218-
* drains the change buffer and removes spans from the WASM map, so with no
1219-
* await between groups nothing can finish into a half-staged flush, and the
1220-
* string table can be evicted exactly once at a provably drained point.
1212+
* One request per group, sequentially. The native `prepared_spans` Vec does
1213+
* accumulate (libdatadog-nodejs #159) and `sendPreparedChunk` would drain all of
1214+
* it into a single multi-trace payload, so batching the whole flush into one
1215+
* request is possible - but it changes what a consumer sees per payload, and
1216+
* `traces[0]` consumers (the test agent among them) rely on one trace per
1217+
* payload, which is also what the legacy AgentWriter produced at the flush
1218+
* intervals these paths run with. Sending per group also keeps a failed send
1219+
* from taking unrelated traces down with it.
12211220
*
12221221
* @param {Array<{spanIds: Uint8Array[], firstIsLocalRoot: boolean}>} groups
12231222
* @returns {Promise<string>} The agent response body, or a no-op marker
12241223
*/
12251224
flushSpansGrouped (groups) {
12261225
// Drain all pending ops (creates, tags, per-trace sampling/trace tags) once
1227-
// up front so every chunk staged below sees a fully-applied span map.
1226+
// up front so every chunk prepared below sees a fully-applied span map.
12281227
this.flushChangeQueue()
12291228

1230-
let staged = 0
1231-
try {
1232-
for (const group of groups) {
1233-
if (!group.spanIds?.length) continue
1234-
if (this.#prepareGroup(group)) staged++
1235-
}
1236-
} catch (e) {
1237-
// prepareChunk may throw partway through (`flush_chunk` errors on an
1238-
// absent span id), after consuming some of the change queue or growing
1239-
// WASM memory. Reset JS-side queue state and refresh views so the next
1240-
// caller starts from a known-good baseline. Groups staged before the
1241-
// throw stay staged and ship with the next flush - they are real spans we
1242-
// wanted to send, so delaying beats dropping them.
1243-
this.resetChangeQueue()
1244-
this.#checkDetach()
1245-
log.error('Error preparing spans to flush:', e)
1246-
return Promise.reject(e)
1229+
const pending = []
1230+
for (const group of groups) {
1231+
if (group.spanIds?.length) pending.push(group)
12471232
}
12481233

1249-
// Safe here and only here: `prepareChunk` drained the change buffer and
1250-
// resolved every interned id into the staged spans, and nothing can have
1251-
// queued an op since (staging above is synchronous). `#evictStringTable(true)`
1252-
// also resets `_stringIdCounter`, so running it while ops are queued - e.g.
1253-
// from a `.finally()` after the async send - would re-issue live ids to
1254-
// different strings and silently mis-tag exported spans.
1255-
this.#evictStringTable(true)
1256-
1257-
if (staged === 0) return Promise.resolve('no spans to flush')
1234+
if (pending.length === 0) {
1235+
this.#evictStringTable(true)
1236+
return Promise.resolve('no spans to flush')
1237+
}
12581238

1259-
const send = this._state.sendPreparedChunk()
1260-
this.#sendInFlight = send
1261-
const clearSend = () => {
1262-
if (this.#sendInFlight === send) this.#sendInFlight = null
1239+
// Sequential: `sendPreparedChunk` also guards against async re-entrancy, and
1240+
// staging the next chunk while one is in flight would put it in the same
1241+
// payload as the current one.
1242+
let chain = Promise.resolve('no spans to flush')
1243+
for (let i = 0; i < pending.length; i++) {
1244+
const group = pending[i]
1245+
const isLast = i === pending.length - 1
1246+
chain = chain.then(() => this.#prepareAndSend(group, isLast))
12631247
}
1264-
send.then(clearSend, clearSend)
12651248

1266-
return send
1249+
return chain
12671250
.catch(e => {
12681251
// A send failure is a *network* fault for the already-serialized chunks;
1269-
// `sendPreparedChunk` took them out of the native Vec before sending, so
1270-
// they are lost, which is expected on a transient agent outage.
1252+
// those are lost, which is expected on a transient agent outage.
12711253
//
12721254
// Crucially, do NOT resetChangeQueue() here. sendPreparedChunk is async,
12731255
// so by the time this rejection lands, ops for *other* spans (including
@@ -1288,6 +1270,55 @@ class NativeSpansInterface {
12881270
})
12891271
}
12901272

1273+
/**
1274+
* Stage one trace's chunk and send it. Rejects if staging throws, after
1275+
* restoring JS-side queue state.
1276+
*
1277+
* @param {{spanIds: Uint8Array[], firstIsLocalRoot: boolean}} group
1278+
* @param {boolean} isLast Whether this is the final group of the flush
1279+
* @returns {Promise<string>}
1280+
*/
1281+
#prepareAndSend (group, isLast) {
1282+
// Every group after the first runs in a `.then()` after an HTTP response, so
1283+
// spans that finished during that send have queued ops. `prepareChunk` calls
1284+
// `flush_change_buffer` internally, which zeroes the WASM header without
1285+
// touching our `_cqbIndex`/`_cqbCount` — drain through our own path first so
1286+
// the two stay in sync (same hazard `setMetaStruct` documents). A no-op when
1287+
// the queue is already empty.
1288+
this.flushChangeQueue()
1289+
1290+
let staged
1291+
try {
1292+
staged = this.#prepareGroup(group)
1293+
} catch (e) {
1294+
// prepareChunk may throw partway through, after consuming some of the
1295+
// change queue or growing WASM memory. Reset JS-side queue state and
1296+
// refresh views so the next caller starts from a known-good baseline.
1297+
this.resetChangeQueue()
1298+
this.#checkDetach()
1299+
log.error('Error preparing spans to flush:', e)
1300+
return Promise.reject(e)
1301+
}
1302+
1303+
// Evict only here, and only on the last group: `prepareChunk` has just
1304+
// drained the change buffer, so no queued op can still reference an id we
1305+
// are about to evict — and `#evictStringTable(true)` also resets
1306+
// `_stringIdCounter`, so running it while ops are queued (e.g. from a
1307+
// `.finally()` after the async send) would re-issue live ids to different
1308+
// strings and silently mis-tag exported spans.
1309+
if (isLast) this.#evictStringTable(true)
1310+
1311+
if (!staged) return Promise.resolve('no spans to flush')
1312+
1313+
const send = this._state.sendPreparedChunk()
1314+
this.#sendInFlight = send
1315+
const clearSend = () => {
1316+
if (this.#sendInFlight === send) this.#sendInFlight = null
1317+
}
1318+
send.then(clearSend, clearSend)
1319+
return send
1320+
}
1321+
12911322
// Note: sample() is not available in the WASM pipeline module.
12921323
// Sampling is handled by the JS-side priority sampler.
12931324
}

packages/dd-trace/test/native/exporter.spec.js

Lines changed: 16 additions & 50 deletions
Original file line numberDiff line numberDiff line change
@@ -192,14 +192,14 @@ describe('NativeExporter', () => {
192192
sinon.assert.calledOnce(logWarn)
193193
})
194194

195-
it('counts one export attempt and success per flush, tagged with the payload span total', async () => {
196-
// `flushSpansGrouped` issues ONE request for the whole flush, so these
197-
// mirror the deleted JS OTLP exporter's per-request counters: one increment
198-
// each, tagged with every span in the payload - not one per trace chunk.
195+
it('counts an export attempt and success per chunk, tagged with that chunk span count', async () => {
196+
// `flushSpansGrouped` issues one HTTP request per trace chunk, so these
197+
// mirror the deleted JS OTLP exporter exactly: its `export()` was invoked
198+
// per chunk and emitted one increment tagged with that chunk's span count.
199199
exporter = new NativeExporter(config, prioritySampler, nativeSpans)
200200

201-
// Two traces of 2 and 3 spans: 5 spans in 2 groups, so a `spans:` tag built
202-
// from the group count is distinguishable from the real span total.
201+
// Two traces of 2 and 3 spans, so a `spans:` tag built from the whole-flush
202+
// total is distinguishable from the per-chunk counts.
203203
const traceA = [createMockSpan(1n), createMockSpan(2n)]
204204
const traceB = [createMockSpan(3n), createMockSpan(4n), createMockSpan(5n)]
205205
for (const span of traceA) span.context()._trace = traceA[0].context()._trace
@@ -211,8 +211,10 @@ describe('NativeExporter', () => {
211211

212212
assert.strictEqual(nativeSpans.flushSpansGrouped.getCall(0).args[0].length, 2)
213213
assert.deepStrictEqual(telemetryCounts, [
214-
{ metric: 'otel.traces_export_attempts', tags: ['protocol:http', 'encoding:json', 'spans:5'] },
215-
{ metric: 'otel.traces_export_successes', tags: ['protocol:http', 'encoding:json', 'spans:5'] },
214+
{ metric: 'otel.traces_export_attempts', tags: ['protocol:http', 'encoding:json', 'spans:2'] },
215+
{ metric: 'otel.traces_export_attempts', tags: ['protocol:http', 'encoding:json', 'spans:3'] },
216+
{ metric: 'otel.traces_export_successes', tags: ['protocol:http', 'encoding:json', 'spans:2'] },
217+
{ metric: 'otel.traces_export_successes', tags: ['protocol:http', 'encoding:json', 'spans:3'] },
216218
])
217219
})
218220

@@ -394,41 +396,6 @@ describe('NativeExporter', () => {
394396
assert.strictEqual(exporter._pendingSpans.length, 0)
395397
})
396398

397-
it('splits an oversized payload across sends instead of one unbounded request', async () => {
398-
// Sends are serialized, so while one is in flight flush() only records
399-
// #flushRequested and the pending queue keeps growing for the whole round
400-
// trip - the export()-time trigger cannot bound the payload here.
401-
let release
402-
nativeSpans.flushSpansGrouped = sinon.stub().returns(new Promise(resolve => { release = resolve }))
403-
404-
// First flush takes the whole (small) batch and is now in flight.
405-
exporter.export([createMockSpan(1n)])
406-
exporter.flush()
407-
sinon.assert.calledOnce(nativeSpans.flushSpansGrouped)
408-
409-
// 12_000 spans arrive as 12 chunks of 1000 while that send is in flight.
410-
for (let c = 0; c < 12; c++) {
411-
const chunk = []
412-
for (let i = 0; i < 1000; i++) chunk.push(createMockSpan(BigInt(c * 1000 + i + 2)))
413-
exporter.export(chunk)
414-
}
415-
assert.strictEqual(exporter._pendingSpans.length, 12_000)
416-
sinon.assert.calledOnce(nativeSpans.flushSpansGrouped)
417-
418-
// The 12_000 backlog must not go out as one request: the next send carries
419-
// 10 whole chunks (10_000 spans) and the 2_000-span remainder follows in its
420-
// own request, without waiting out another flushInterval.
421-
nativeSpans.flushSpansGrouped = sinon.stub().resolves('OK')
422-
release('OK')
423-
await clock.tickAsync(0)
424-
425-
const sizes = nativeSpans.flushSpansGrouped.getCalls()
426-
.map(call => call.args[0].reduce((total, group) => total + group.spanIds.length, 0))
427-
assert.deepStrictEqual(sizes, [10_000, 2000])
428-
assert.strictEqual(exporter._pendingSpans.length, 0)
429-
assert.strictEqual(exporter._pendingSpanChunks.length, 0)
430-
})
431-
432399
it('resets native state immediately when explicitly requested while idle', () => {
433400
exporter._resetNativeStateWhenIdle()
434401

@@ -958,10 +925,10 @@ describe('NativeExporter', () => {
958925
describe('health metrics', () => {
959926
const P = 'datadog.tracer.node.exporter.agent'
960927

961-
it('increments request + response counters once per flush, not once per trace', async () => {
962-
// Two traces coalesce into two chunks but ONE request, so these counters
963-
// must fire once - the same per-request scale as `.errors`. Counting per
964-
// chunk multiplies every native user's request rate by traces-per-flush.
928+
it('increments request + response counters once per trace chunk', async () => {
929+
// `flushSpansGrouped` issues one HTTP request per chunk, so these counters
930+
// must scale with chunks to stay on the same per-attempt footing as
931+
// `.errors`. A single per-flush increment reports 1/N of the real volume.
965932
exporter = new NativeExporter(config, prioritySampler, nativeSpans)
966933
exporter.export([createMockSpan(1n)])
967934
exporter.export([createMockSpan(2n)])
@@ -970,10 +937,9 @@ describe('NativeExporter', () => {
970937

971938
const groups = nativeSpans.flushSpansGrouped.getCall(0).args[0]
972939
assert.strictEqual(groups.length, 2)
973-
sinon.assert.calledOnce(nativeSpans.flushSpansGrouped)
974940
const counted = metric => metricsIncrement.args.filter(([name]) => name === metric).length
975-
assert.strictEqual(counted(`${P}.requests`), 1)
976-
assert.strictEqual(counted(`${P}.responses`), 1)
941+
assert.strictEqual(counted(`${P}.requests`), 2)
942+
assert.strictEqual(counted(`${P}.responses`), 2)
977943
})
978944

979945
it('increments error counters (name + code) on a failed flush', async () => {

0 commit comments

Comments
 (0)