perf: reduce per-request tracing overhead

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
 

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);
+});

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`);
+});

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);
+});

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}`);
   }

lib/id.js

@@ -1,31 +1,45 @@
 'use strict';
 
+const { Buffer } = require('node:buffer');
 const { randomFillSync } = require('node:crypto');
 
 // A 4KB buffer of random bytes, refilled when exhausted (once every ~170
 // spans: 16 bytes per trace ID, 8 per span ID), amortizes the CSPRNG cost.
 // 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);

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}`);