feat: populate dnslookup timing with actual DNS resolution time

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

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

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'),

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