diff --git a/README.md b/README.md index 3147212a..6f8c130c 100644 --- a/README.md +++ b/README.md @@ -203,6 +203,45 @@ Response is normal object, it contains: - `timing`: timing object if timing enable. - `socket`: socket info +### Timing + +All timing values are milliseconds elapsed from the start of the request. Enable via `options.timing = true` (default). + +``` + ┌──────────┬──────────┬──────────┬─────────────────┬─────────────┬─────────┬─────────────────┐ + │ Queuing │ DNS │ TCP │ Request │ Request │ Waiting │ Content │ + │ │ Lookup │ Connect │ Headers Sent │ Body Sent │ (TTFB) │ Download │ + └──────────┴──────────┴──────────┴─────────────────┴─────────────┴─────────┴─────────────────┘ + | | | | | | | | + 0 queuing dnslookup connected requestHeadersSent requestSent waiting contentDownload +``` + +| Field | Description | +| -------------------- | ------------------------------------------------------------------------------------ | +| `queuing` | Socket pool queuing time. The socket has been assigned to the request. | +| `dnslookup` | DNS lookup completed (only on first request of a new socket, `0` on reused sockets). | +| `connected` | TCP (or TLS) connection is established. | +| `requestHeadersSent` | Request headers have been written to the socket. | +| `requestSent` | Full request (headers + body) has been sent. | +| `waiting` | Time to First Byte (TTFB). Response headers have been received. | +| `contentDownload` | Response body and trailers have been fully received. | + +Example: + +```json +{ + "queuing": 2.8, + "dnslookup": 9.0, + "connected": 12.7, + "requestHeadersSent": 13.4, + "requestSent": 13.6, + "waiting": 24.0, + "contentDownload": 25.1 +} +``` + +> **Note**: `dnslookup` is `0` when the socket is reused from the pool (keep-alive), since no DNS resolution occurs. + ## Run test with debug log ```bash diff --git a/src/diagnosticsChannel.ts b/src/diagnosticsChannel.ts index 2b07a75e..b813a565 100644 --- a/src/diagnosticsChannel.ts +++ b/src/diagnosticsChannel.ts @@ -87,6 +87,18 @@ export function initDiagnosticsChannel(): void { if (initedDiagnosticsChannel) return; initedDiagnosticsChannel = true; + // capture DNS lookup time on socket via net.client.socket diagnostics channel + // this channel fires when a new TCP/IPC connection is initiated, giving us + // access to the socket before the 'lookup' event fires + subscribe('net.client.socket', (message: unknown) => { + const socket = (message as { socket: SocketExtend }).socket; + if (socket) { + socket.once('lookup', () => { + socket[symbols.kSocketDnsLookupTime] = performance.now(); + }); + } + }); + let kHandler: symbol; // This message is published when a new outgoing request is created. // Note: a request is only loosely completed to a given socket. @@ -201,6 +213,13 @@ export function initDiagnosticsChannel(): void { opaque[symbols.kRequestStartTime], socket[symbols.kSocketStartTime] as number, ); + // kSocketDnsLookupTime - kRequestStartTime = dns lookup time + if (socket[symbols.kSocketDnsLookupTime] !== undefined) { + opaque[symbols.kRequestTiming].dnslookup = performanceTime( + opaque[symbols.kRequestStartTime], + socket[symbols.kSocketDnsLookupTime] as number, + ); + } } }); diff --git a/src/symbols.ts b/src/symbols.ts index 27774b82..aa2374c0 100644 --- a/src/symbols.ts +++ b/src/symbols.ts @@ -9,6 +9,7 @@ const symbols: { kSocketConnectHost: symbol; kSocketConnectPort: symbol; kSocketConnectProtocol: symbol; + kSocketDnsLookupTime: symbol; kHandledRequests: symbol; kHandledResponses: symbol; kRequestSocket: symbol; @@ -30,6 +31,7 @@ const symbols: { kSocketConnectHost: Symbol('socket connect params: host'), kSocketConnectPort: Symbol('socket connect params: port'), kSocketConnectProtocol: Symbol('socket connect params: protocol'), + kSocketDnsLookupTime: Symbol('socket dns lookup time'), kHandledRequests: Symbol('handled requests per socket'), kHandledResponses: Symbol('handled responses per socket'), kRequestSocket: Symbol('request on the socket'), diff --git a/test/options.timing.test.ts b/test/options.timing.test.ts index f99e5817..69214ff2 100644 --- a/test/options.timing.test.ts +++ b/test/options.timing.test.ts @@ -30,6 +30,8 @@ describe('options.timing.test.ts', () => { assert(res.timing.waiting > 0); assert(res.timing.queuing > 0); assert(res.timing.connected > 0); + assert(res.timing.dnslookup >= 0); + assert(res.timing.dnslookup <= res.timing.connected); assert(res.timing.requestHeadersSent > 0); assert(res.timing.requestSent > 0); assert(res.timing.contentDownload > 0); @@ -49,6 +51,7 @@ describe('options.timing.test.ts', () => { assert(res.timing.waiting > 0); assert(res.timing.queuing > 0); assert.equal(res.timing.connected, 0); + assert.equal(res.timing.dnslookup, 0); assert(res.timing.requestHeadersSent > 0); assert(res.timing.requestSent > 0); assert(res.timing.contentDownload > 0);