diff --git a/README.md b/README.md index b4cf5db..2941217 100644 --- a/README.md +++ b/README.md @@ -193,17 +193,22 @@ the limitations below. ## Benchmarks -The HTTP benchmark uses the experimental `node:bench` runner, which is also -what sets the package's Node.js floor (`engines` requires 26.9.0 or newer): +The benchmarks use the experimental `node:bench` runner, which is also what +sets the package's Node.js floor (`engines` requires 26.9.0 or newer): ```bash node --experimental-bench --bench 'benchmark/*.bench.js' ``` -The traced and untraced configurations live in separate files: the runner -executes each file in its own child process, and tracing activates at most -once per process. The traced run exports to a local dummy collector, so the -measurement includes the export round trip. +The traced and untraced HTTP and fetch configurations live in separate +files: the runner executes each file in its own child process, and tracing +activates at most once per process. The traced runs export to a local dummy +collector in the same process, so the measurement includes the export work +done while the requests run. + +Smaller benchmarks time pieces of that work on their own: building client +and server spans, generating IDs into a `traceparent` value, and exporting +batches of spans until the collector has received the last one. ## Current limitations diff --git a/benchmark/export.bench.js b/benchmark/export.bench.js new file mode 100644 index 0000000..03ab4db --- /dev/null +++ b/benchmark/export.bench.js @@ -0,0 +1,75 @@ +'use strict'; + +const { after, before, bench } = require('node:bench'); +const http = require('node:http'); +const microtel = require('../index'); +const { Span, SPAN_KIND_CLIENT } = require('../lib/span'); + +const kBatchesPerSample = 20; +const kSpansPerBatch = 100; +// A sample takes a few milliseconds. Failed exports only warn, so a lost +// batch would otherwise leave the sample waiting forever. +const kSampleTimeoutMs = 5000; + +let collector; +let received = 0; +let onReceived = () => {}; + +before(async () => { + collector = http.createServer((req, res) => { + req.resume(); + req.on('end', () => { + res.end(); + received++; + onReceived(); + }); + }); + await new Promise((resolve) => collector.listen(0, '127.0.0.1', resolve)); + microtel.init({ + endpoint: `http://127.0.0.1:${collector.address().port}`, + // Each batch is flushed by hand, so the buffer never fills on its own. + maxBufferSize: kSpansPerBatch + 1, + }); +}); + +after(() => new Promise((resolve) => collector.close(resolve))); + +// Covers ending spans, serializing each batch, and sending it, up to the +// collector receiving the last batch. flush() does not report when its +// export finishes, so the collector counts the batches instead. +bench('export spans to a collector', { samples: 30 }, async (b) => { + const target = received + kBatchesPerSample; + let watchdog; + const done = new Promise((resolve, reject) => { + onReceived = () => { + if (received >= target) resolve(); + }; + watchdog = setTimeout(() => { + const missing = target - received; + reject( + new Error( + `${missing} of ${kBatchesPerSample} batches never reached the collector`, + ), + ); + }, kSampleTimeoutMs); + }); + + b.start(); + for (let batch = 0; batch < kBatchesPerSample; batch++) { + for (let i = 0; i < kSpansPerBatch; i++) { + const span = new Span('GET', SPAN_KIND_CLIENT); + span.setAttribute('http.request.method', 'GET'); + span.setAttribute('url.full', 'http://127.0.0.1/path?query=ascii'); + span.setAttribute('server.address', '127.0.0.1'); + span.setAttribute('server.port', 80); + span.end(); + } + microtel.flush(); + } + try { + await done; + } finally { + clearTimeout(watchdog); + } + b.end(kBatchesPerSample * kSpansPerBatch); +}); diff --git a/benchmark/id.bench.js b/benchmark/id.bench.js new file mode 100644 index 0000000..51362ef --- /dev/null +++ b/benchmark/id.bench.js @@ -0,0 +1,21 @@ +'use strict'; + +const { bench } = require('node:bench'); +const { generateSpanId, generateTraceId } = require('../lib/id'); + +const kValuesPerSample = 100_000; + +// The check setHeader applies to a header value. It flattens any string +// built by concatenation, so how an ID was built shows up here too. +const kInvalidHeaderChar = /[^\t\x20-\x7e\x80-\xff]/; + +bench('IDs into a traceparent value', { samples: 30 }, (b) => { + let invalid = 0; + b.start(); + for (let i = 0; i < kValuesPerSample; i++) { + const value = `00-${generateTraceId()}-${generateSpanId()}-01`; + if (kInvalidHeaderChar.test(value)) invalid++; + } + b.end(kValuesPerSample); + if (invalid !== 0) throw new Error(`${invalid} invalid traceparent values`); +}); diff --git a/benchmark/span.bench.js b/benchmark/span.bench.js new file mode 100644 index 0000000..3fe10e7 --- /dev/null +++ b/benchmark/span.bench.js @@ -0,0 +1,42 @@ +'use strict'; + +const { bench } = require('node:bench'); +const { Span, SPAN_KIND_CLIENT, SPAN_KIND_SERVER } = require('../lib/span'); + +const kSpansPerSample = 100_000; +const kTraceparent = '00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01'; + +// Spans stay alive in a ring, so allocation and GC behave as they do while +// spans wait for export. They are never ended, so nothing is exported. +const ring = Array.from({ length: 1024 }); + +bench('client span construction', { samples: 30 }, (b) => { + b.start(); + for (let i = 0; i < kSpansPerSample; i++) { + const span = new Span('GET', SPAN_KIND_CLIENT); + span.setAttribute('http.request.method', 'GET'); + span.setAttribute('server.address', '127.0.0.1'); + span.setAttribute('server.port', 8080); + span.setAttribute('url.full', 'http://127.0.0.1:8080/api/data'); + span.setAttribute('network.protocol.version', '1.1'); + span.setAttribute('http.response.status_code', 200); + ring[i & 1023] = span; + } + b.end(kSpansPerSample); +}); + +bench('server span from a traceparent', { samples: 30 }, (b) => { + b.start(); + for (let i = 0; i < kSpansPerSample; i++) { + const parent = Span.fromTraceparent(kTraceparent); + const span = new Span('GET', SPAN_KIND_SERVER, { parent }); + span.setAttribute('http.request.method', 'GET'); + span.setAttribute('url.path', '/api/data'); + span.setAttribute('url.scheme', 'http'); + span.setAttribute('network.protocol.version', '1.1'); + span.setAttribute('server.address', '127.0.0.1'); + span.setAttribute('http.response.status_code', 200); + ring[i & 1023] = span; + } + b.end(kSpansPerSample); +}); diff --git a/lib/flush.js b/lib/flush.js index 775ada7..93272cf 100644 --- a/lib/flush.js +++ b/lib/flush.js @@ -231,6 +231,11 @@ function sendToCollector(body) { const transport = parsed.protocol === 'https:' ? https : http; + // Encoding once serves both the length and the write. A string body is + // scanned for its byte length, then joined to the header block and + // encoded again on write. + const encoded = Buffer.from(body); + const req = transport.request( { hostname: parsed.hostname, @@ -240,7 +245,7 @@ function sendToCollector(body) { agent: kExportAgents[parsed.protocol], headers: { 'content-type': 'application/json', - 'content-length': Buffer.byteLength(body), + 'content-length': encoded.length, }, }, (res) => { @@ -283,7 +288,7 @@ function sendToCollector(body) { ); }); - req.end(body); + req.end(encoded); } catch (err) { warnExportFailure(`Failed to export spans to ${endpoint}: ${err.message}`); } diff --git a/lib/id.js b/lib/id.js index c58881b..52dce35 100644 --- a/lib/id.js +++ b/lib/id.js @@ -1,5 +1,6 @@ 'use strict'; +const { Buffer } = require('node:buffer'); const { randomFillSync } = require('node:crypto'); // A 4KB buffer of random bytes, refilled when exhausted (once every ~170 @@ -7,25 +8,38 @@ const { randomFillSync } = require('node:crypto'); // The CSPRNG stays: the W3C Trace Context spec recommends unpredictable // IDs, and they are visible in outgoing requests. benchmark/ tracks the // per-request overhead. +// +// IDs are slices of a hex string that encodes one chunk of the buffer. +// V8 makes a slice this long a view into that string rather than a copy, +// so one native call encodes the IDs for about five spans. A view keeps +// its whole string alive, though, and a span can outlive its request in +// AsyncLocalStorage, so the chunk is kept small. A span's two IDs pin at +// most two chunk strings. const kBufferSize = 4096; -const randomBuffer = new Uint8Array(kBufferSize); +const kChunkSize = 128; +const randomBuffer = Buffer.allocUnsafeSlow(kBufferSize); let randomOffset = kBufferSize; // Start at end to trigger first fill - -const hexTable = new Array(256); -for (let i = 0; i < 256; i++) hexTable[i] = i.toString(16).padStart(2, '0'); - -function ensureRandomBytes(needed) { - if (randomOffset + needed > kBufferSize) { - randomFillSync(randomBuffer); - randomOffset = 0; - } -} +let hexChunk = ''; +let hexOffset = 0; function generateId(bytes) { - ensureRandomBytes(bytes); - let id = ''; - for (let i = 0; i < bytes; i++) id += hexTable[randomBuffer[randomOffset++]]; - return id; + const chars = 2 * bytes; + if (hexOffset + chars > hexChunk.length) { + if (randomOffset === kBufferSize) { + randomFillSync(randomBuffer); + randomOffset = 0; + } + hexChunk = randomBuffer.toString( + 'hex', + randomOffset, + randomOffset + kChunkSize, + ); + randomOffset += kChunkSize; + hexOffset = 0; + } + const start = hexOffset; + hexOffset += chars; + return hexChunk.slice(start, hexOffset); } const generateTraceId = () => generateId(16); diff --git a/lib/instrumentations.js b/lib/instrumentations.js index cecfa14..5f4334f 100644 --- a/lib/instrumentations.js +++ b/lib/instrumentations.js @@ -91,9 +91,9 @@ function onHttpServerRequestStart({ request, response, socket }) { const host = request.headers.host; if (host) span.setAttribute('server.address', splitAuthority(host)[0]); - // The span is stashed on the request so the response handlers do not + // The span is stashed on the response so the response handlers do not // need a second AsyncLocalStorage lookup. - request[kSpan] = span; + response[kSpan] = span; // The span deliberately stays in the AsyncLocalStorage after the request // ends, so work started while handling it still links to the server @@ -104,16 +104,22 @@ function onHttpServerRequestStart({ request, response, socket }) { // before the response completed. Request 'close' cannot be used for // this: it also fires when the request stream is merely consumed, which // can happen long before a delayed response is sent. - response.on('close', () => { - if (span.endTime === undefined && !response.writableEnded) { - span.setStatus(STATUS_ERROR, 'request closed before response'); - span.end(); - } - }); + response.on('close', onServerResponseClose); } -function onHttpServerResponseFinish({ request, response }) { - const span = request[kSpan]; +// Shared by every server response, so no closure is allocated per +// request. The span is read from the response itself, not through res.req, +// which application code can reassign. +function onServerResponseClose() { + const span = this[kSpan]; + if (span.endTime === undefined && !this.writableEnded) { + span.setStatus(STATUS_ERROR, 'request closed before response'); + span.end(); + } +} + +function onHttpServerResponseFinish({ response }) { + const span = response[kSpan]; if (span == null) return; const statusCode = response.statusCode; @@ -206,11 +212,19 @@ function onHttpClientResponseFinish({ request, response }) { span.setAttribute('network.protocol.version', response.httpVersion || '1.1'); applyClientResponse(span, response.statusCode); - // 'end' fires only when the body has been fully read; 'close' covers - // aborted responses. - const endSpan = () => span.end(); - response.once('end', endSpan); - response.once('close', endSpan); + // 'end' fires only when the body has been fully read, and 'close' + // covers aborted responses. Ending a span twice is a no-op, so plain + // listeners do what once() would without its wrappers. + response[kSpan] = span; + response.on('end', endClientResponseSpan); + response.on('close', endClientResponseSpan); +} + +// Shared by every client response, so no closure is allocated per +// request. The span is read from the response itself, not through res.req, +// which application code can reassign. +function endClientResponseSpan() { + this[kSpan].end(); } function onClientRequestError({ request, error }) { @@ -346,6 +360,13 @@ function removeUndiciHeader(request, name) { } } +// The last origin parsed, and what it yielded. Consecutive fetch requests +// usually go to the same origin, and new URL() is one of the costliest +// steps in this handler. +let lastOrigin; +let lastOriginAddress; +let lastOriginPort; + function onUndiciRequestCreate({ request }) { const parent = spanStorage.getStore(); @@ -357,13 +378,16 @@ function onUndiciRequestCreate({ request }) { const { origin } = request; const path = request.path; if (origin) { - // The origin omits the port when it is the scheme default. - const parsed = new URL(origin); - span.setAttribute('server.address', parsed.hostname); - span.setAttribute( - 'server.port', - Number(parsed.port) || (parsed.protocol === 'https:' ? 443 : 80), - ); + if (origin !== lastOrigin) { + // The origin omits the port when it is the scheme default. + const parsed = new URL(origin); + lastOriginAddress = parsed.hostname; + lastOriginPort = + Number(parsed.port) || (parsed.protocol === 'https:' ? 443 : 80); + lastOrigin = origin; + } + span.setAttribute('server.address', lastOriginAddress); + span.setAttribute('server.port', lastOriginPort); } span.setAttribute('url.full', `${origin}${path}`); diff --git a/lib/span.js b/lib/span.js index 8b8e117..f06a9dc 100644 --- a/lib/span.js +++ b/lib/span.js @@ -17,12 +17,53 @@ const STATUS_ERROR = 2; const kSpan = Symbol('kOtelSpan'); -const kHex32 = /^[0-9a-f]{32}$/; -const kHex16 = /^[0-9a-f]{16}$/; -const kHex2 = /^[0-9a-f]{2}$/; +// The whole version-00 traceparent layout in one test: version, trace ID, +// span ID, and flags, all lowercase hex. +const kTraceparent = /^00-[0-9a-f]{32}-[0-9a-f]{16}-[0-9a-f]{2}$/; const kAllZero32 = '00000000000000000000000000000000'; const kAllZero16 = '0000000000000000'; +// The attribute keys the instrumentations write, preallocated so every +// span's attributes share one shape and writes are plain property stores. +// Unused keys stay undefined and are skipped at export time. A class keeps +// the object in V8's fast mode, where an object literal with __proto__: +// null would start out in dictionary mode. Its prototype has no +// properties and no prototype of its own, so the object inherits nothing, +// and a key named __proto__ is stored as an ordinary own property. +class SpanAttributes { + 'error.type' = undefined; + 'http.request.method' = undefined; + 'http.response.status_code' = undefined; + 'network.protocol.version' = undefined; + 'server.address' = undefined; + 'server.port' = undefined; + 'url.full' = undefined; + 'url.path' = undefined; + 'url.query' = undefined; + 'url.scheme' = undefined; +} +delete SpanAttributes.prototype.constructor; +Object.setPrototypeOf(SpanAttributes.prototype, null); + +// A parent parsed from an inbound traceparent header. A class keeps it in +// V8's fast mode, unlike a __proto__: null literal. The header carries no +// tracestate or baggage, so those stay undefined. +class RemoteParent { + tracestate = undefined; + baggage = undefined; + constructor(traceId, spanId, traceFlags) { + this.traceId = traceId; + this.spanId = spanId; + this.traceFlags = traceFlags; + } +} + +// Spans start with these shared values, so a span without events or a +// status allocates neither. addEvent and setStatus replace them rather +// than mutating them. +const kNoEvents = Object.freeze([]); +const kUnsetStatus = Object.freeze({ code: STATUS_UNSET, message: '' }); + class Span { traceId; spanId; @@ -56,26 +97,9 @@ class Span { this.name = name; this.kind = kind; this.spanId = generateSpanId(); - // The keys below are the complete set the instrumentations write (there - // is no public attribute API yet). Preallocating them keeps every - // span's attribute object the same shape, so writes never trigger - // hidden class transitions or dictionary mode. Unused keys stay - // undefined and are skipped at export time. - this.#attributes = { - __proto__: null, - 'error.type': undefined, - 'http.request.method': undefined, - 'http.response.status_code': undefined, - 'network.protocol.version': undefined, - 'server.address': undefined, - 'server.port': undefined, - 'url.full': undefined, - 'url.path': undefined, - 'url.query': undefined, - 'url.scheme': undefined, - }; - this.#events = []; - this.#status = { code: STATUS_UNSET, message: '' }; + this.#attributes = new SpanAttributes(); + this.#events = kNoEvents; + this.#status = kUnsetStatus; this.startTime = Date.now(); this.#startMonotonic = performance.now(); @@ -112,6 +136,7 @@ class Span { // Only the internal exception producer uses events today; cap them // once addEvent becomes part of a public API. // TODO(bengl): cap the number of events per span then. + if (this.#events === kNoEvents) this.#events = []; this.#events.push({ name, // Anchored to the span start like endTime, for clock-step safety. @@ -157,28 +182,19 @@ class Span { // when invalid per the W3C spec. static fromTraceparent(traceparentHeader) { if (typeof traceparentHeader !== 'string') return null; + // Only version 00 is defined, so anything else is rejected. + if (!kTraceparent.test(traceparentHeader)) return null; - const parts = traceparentHeader.split('-'); - if (parts.length !== 4) return null; - - // Only version 00 is defined; reject everything else. - if (parts[0] !== '00') return null; - const traceId = parts[1]; - const spanId = parts[2]; - const flags = parts[3]; - if (!kHex32.test(traceId)) return null; - if (!kHex16.test(spanId)) return null; - if (!kHex2.test(flags)) return null; - + const traceId = traceparentHeader.slice(3, 35); + const spanId = traceparentHeader.slice(36, 52); if (traceId === kAllZero32) return null; if (spanId === kAllZero16) return null; - return { - __proto__: null, + return new RemoteParent( traceId, spanId, - traceFlags: parseInt(flags, 16), - }; + parseInt(traceparentHeader.slice(53, 55), 16), + ); } } diff --git a/test/test-http-client.js b/test/test-http-client.js index 73db244..380ce1c 100644 --- a/test/test-http-client.js +++ b/test/test-http-client.js @@ -280,4 +280,31 @@ describe('otel HTTP client spans', () => { const exceptionEvent = errorSpan.events.find((e) => e.name === 'exception'); assert.ok(exceptionEvent, 'Should have exception event'); }); + + // Application code can reassign res.req, so the span must not be found + // through it. Node itself needs res.req until the body ends, but not for + // the 'close' that follows. + it('survives res.req being reassigned after the body ends', async () => { + const target = await startHTTPServer((req, res) => res.end('ok')); + + await new Promise((resolve, reject) => { + http + .get(`http://127.0.0.1:${target.port}/reassigned`, (res) => { + res.resume(); + res.on('end', () => { + res.req = undefined; + }); + res.on('close', resolve); + }) + .on('error', reject); + }); + const spans = await flushAndCollect(collector); + + await target.close(); + + assert.ok( + getClientSpan(spans, '/reassigned'), + 'Expected a client span for /reassigned', + ); + }); }); diff --git a/test/test-id-refill.js b/test/test-id-refill.js index 365d4d3..50743a5 100644 --- a/test/test-id-refill.js +++ b/test/test-id-refill.js @@ -25,4 +25,17 @@ describe('otel ID generation buffer refill', () => { assert.strictEqual(ids.size, count); }); } + + it('never reuses random bytes when trace and span IDs interleave', () => { + // A trace ID that does not fit the rest of a chunk starts a new one, + // so every 8-byte piece of every ID must be distinct. + const pieces = new Set(); + let total = 0; + for (let i = 0; i < 1000; i++) { + const id = i % 3 === 0 ? generateSpanId() : generateTraceId(); + for (let j = 0; j < id.length; j += 16, total++) + pieces.add(id.slice(j, j + 16)); + } + assert.strictEqual(pieces.size, total); + }); }); diff --git a/test/test-server-close.js b/test/test-server-close.js index 8d086a4..f0547e4 100644 --- a/test/test-server-close.js +++ b/test/test-server-close.js @@ -3,20 +3,25 @@ const assert = require('node:assert'); const http = require('node:http'); const net = require('node:net'); -const { describe, it } = require('node:test'); +const { after, before, describe, it } = require('node:test'); const { flush } = require('../lib/flush'); const { startTracing, startHTTPServer, getSpans, getServerSpan, - closeAll, } = require('./common/otel'); describe('otel server request close handling', () => { - it('ends span with error when client disconnects before response', async () => { - const collector = await startTracing(); + let collector; + before(async () => { + collector = await startTracing(); + }); + + after(() => collector.close()); + + async function testDisconnect(reassignReq) { // Create a server that delays its response for every path except // /flush, which responds normally and is used to trigger an export. const server = await startHTTPServer((req, res) => { @@ -25,6 +30,7 @@ describe('otel server request close handling', () => { res.end('ok'); return; } + if (reassignReq) res.req = undefined; // Don't respond — the client will disconnect first. req.on('close', () => { // After the client disconnects, make a normal request and flush. @@ -45,12 +51,20 @@ describe('otel server request close handling', () => { const spans = getSpans(await collector.next()); - await closeAll(collector, server); + await server.close(); const disconnectSpan = getServerSpan(spans, '/disconnect'); assert.ok(disconnectSpan, 'Expected a server span for /disconnect'); assert.ok(disconnectSpan.status, 'Span should have error status'); assert.strictEqual(disconnectSpan.status.code, 2); // STATUS_ERROR - }); + } + + it('ends span with error when client disconnects before response', () => + testDisconnect(false)); + + // Application code can reassign res.req, so the span must not be found + // through it. + it('ends span with error after the handler reassigns res.req', () => + testDisconnect(true)); }); diff --git a/test/test-traceparent-validation.js b/test/test-traceparent-validation.js index 2e1002a..5eb9dc0 100644 --- a/test/test-traceparent-validation.js +++ b/test/test-traceparent-validation.js @@ -1,7 +1,9 @@ 'use strict'; const assert = require('node:assert'); +const { inspect } = require('node:util'); const { after, before, describe, it } = require('node:test'); +const { Span } = require('../lib/span'); const { startTracing, startHTTPServer, @@ -90,3 +92,54 @@ describe('otel traceparent validation', () => { ); }); }); + +describe('otel traceparent parsing', () => { + const traceId = '0af7651916cd43dd8448eb211c80319c'; + const spanId = 'b7ad6b7169203331'; + const header = (flags) => `00-${traceId}-${spanId}-${flags}`; + + it('parses version 00 headers with any flags', () => { + for (const [flags, traceFlags] of [ + ['00', 0], + ['01', 1], + ['ff', 255], + ]) + assert.partialDeepStrictEqual(Span.fromTraceparent(header(flags)), { + traceId, + spanId, + traceFlags, + }); + }); + + it('rejects every other layout', () => { + const invalid = [ + `01-${traceId}-${spanId}-01`, + `ff-${traceId}-${spanId}-01`, + `00-${'0'.repeat(32)}-${spanId}-01`, + `00-${traceId}-${'0'.repeat(16)}-01`, + `00-${traceId.toUpperCase()}-${spanId}-01`, + `00-${traceId}-${spanId.toUpperCase()}-01`, + header('0A'), + header('0\u0661'), + `00-${traceId.slice(1)}-${spanId}-01`, + `00-${traceId}0-${spanId}-01`, + `00-${traceId}-${spanId.slice(1)}-01`, + header('1'), + header('001'), + `00-${traceId}${spanId}-01`, + `00--${traceId}-${spanId}-01`, + `${header('01')}-01`, + `${header('01')}\n`, + `${header('01')}\r`, + `${header('01')}\r\n`, + ` ${header('01')}`, + '', + undefined, + null, + 1, + [header('01')], + ]; + for (const value of invalid) + assert.strictEqual(Span.fromTraceparent(value), null, inspect(value)); + }); +});