Support request timing data in nodejs (#68)

Co-authored-by: Kevin Paxton <kevin.paxton@formidable.com>

.changeset/tame-beans-mate.md

@@ -0,0 +1,7 @@
+---
+'@envyjs/webui': patch
+'@envyjs/core': patch
+'@envyjs/node': patch
+---
+
+Support HAR timing data

packages/core/src/http.ts

@@ -59,6 +59,53 @@ export interface HttpRequest {
    */
   statusMessage?: string;
 
+  /**
+   * HAR formatted timing information
+   *
+   * http://www.softwareishard.com/blog/har-12-spec/#timings
+   */
+  timings?: {
+    /**
+     * Time spent in a queue waiting for a network connection.
+     * -1 if the timing does not apply to the current request.
+     */
+    blocked: number;
+
+    /**
+     * DNS resolution time. The time required to resolve a host name.
+     * -1 if the timing does not apply to the current request.
+     */
+    dns: number;
+
+    /**
+     * Time required for SSL/TLS negotiation.
+     * If this field is defined then the time is also included in the connect field (to ensure backward compatibility with HAR 1.1).
+     * -1 if the timing does not apply to the current request.
+     */
+    ssl: number;
+
+    /**
+     * Time required to create TCP connection.
+     * -1 if the timing does not apply to the current request.
+     */
+    connect: number;
+
+    /**
+     * Time required to send HTTP request to the server.
+     */
+    send: number;
+
+    /**
+     * Waiting for a response from the server.
+     */
+    wait: number;
+
+    /**
+     * Time required to read entire response from the server (or cache).
+     */
+    receive: number;
+  };
+
   /**
    * The full url of the request
    */

packages/node/src/http.ts

@@ -1,38 +1,29 @@
 import http from 'http';
 import https from 'https';
-import { types as utilTypes } from 'util';
+import process from 'process';
 
-import { Event, HttpRequest } from '@envyjs/core';
-import { wrap } from 'shimmer';
+import { Event, HttpRequest, Plugin } from '@envyjs/core';
 
 // eslint thinks zlib is node20:builtin, but this is a node module
 // eslint-disable-next-line import/order
 import { createBrotliDecompress, unzip } from 'zlib';
 
 import { generateId } from './id';
 import log from './log';
-import { Plugin } from '@envyjs/core';
-
-// ESM handling of wrapping
-const _wrap: typeof wrap = (moduleExports, name, wrapper) => {
-  if (!utilTypes.isProxy(moduleExports)) {
-    return wrap(moduleExports, name, wrapper);
-  } else {
-    const wrapped = wrap(Object.assign({}, moduleExports), name, wrapper);
-
-    return Object.defineProperty(moduleExports, name, {
-      value: wrapped,
-    });
-  }
-};
+import { Timestamps, calculateTiming, getDuration } from './utils/time';
+import { wrap } from './utils/wrap';
 
 export const Http: Plugin = (_options, exporter) => {
   function override(module: any) {
-    _wrap(module, 'request', (original: any) => {
+    wrap(module, 'request', (original: any) => {
       return function (this: any, ...args: http.ClientRequestArgs[]) {
         const id = generateId();
         const startTs = Date.now();
 
+        const _timestamps: Timestamps = {
+          start: process.hrtime(),
+        };
+
         const request = original.apply(this, args) as http.ClientRequest;
         const write = request.write;
         const end = request.end;
@@ -58,6 +49,40 @@ export const Http: Plugin = (_options, exporter) => {
           },
         };
 
+        // collect timing data
+        let removeSocketListeners: () => void;
+        request.on('socket', socket => {
+          _timestamps.socket = process.hrtime();
+
+          const onLookup = () => {
+            _timestamps.lookup = process.hrtime();
+          };
+
+          const onConnect = () => {
+            _timestamps.connect = process.hrtime();
+          };
+
+          const onSecureConnect = () => {
+            _timestamps.secureConnect = process.hrtime();
+          };
+
+          socket.once('lookup', onLookup);
+          socket.once('connect', onConnect);
+          socket.once('secureConnect', onSecureConnect);
+
+          removeSocketListeners = () => {
+            socket.removeListener('lookup', onLookup);
+            socket.removeListener('connect', onConnect);
+            socket.removeListener('secureConnect', onSecureConnect);
+          };
+        });
+        request.on('finish', () => {
+          _timestamps.sent = process.hrtime();
+          if (removeSocketListeners) removeSocketListeners();
+        });
+
+        // captures the request payload and waits until
+        // the caller is done writing to the stream
         const payload: any = [];
         request.write = function (...args: any) {
           const chunk = args[0];
@@ -76,7 +101,21 @@ export const Http: Plugin = (_options, exporter) => {
           return end.apply(this, args);
         };
 
+        // captures the response
         request.addListener('response', response => {
+          _timestamps.firstByte = process.hrtime();
+
+          // Now we know whether `lookup` or `connect` happened. It's possible they
+          // were skipped if the hostname was already resolved (or we were given an
+          // IP directly), or if a connection was already open (e.g. due to
+          // `keep-alive`).
+          if (!_timestamps.lookup) {
+            _timestamps.lookup = _timestamps.socket;
+          }
+          if (!_timestamps.connect) {
+            _timestamps.connect = _timestamps.lookup;
+          }
+
           const payload: any = [];
 
           const onRequestData = (chunk: any) => {
@@ -86,14 +125,11 @@ export const Http: Plugin = (_options, exporter) => {
           };
 
           const onRequestEnd = () => {
-            const endTs = Date.now();
-
             const httpResponse: Event = {
               ...httpRequest,
 
               http: {
                 ...httpRequest.http!,
-                duration: endTs - startTs,
                 httpVersion: response.httpVersion,
                 responseBody: undefined,
                 responseHeaders: response.headers,
@@ -103,7 +139,12 @@ export const Http: Plugin = (_options, exporter) => {
             };
 
             parsePayload(httpResponse.http!, payload, body => {
+              _timestamps.received = process.hrtime();
+
               httpResponse.http!.responseBody = body;
+              httpResponse.http!.timings = calculateTiming(_timestamps);
+              httpResponse.http!.duration = getDuration(_timestamps.start, _timestamps.received);
+
               exporter.send(httpResponse);
             });
           };

packages/node/src/utils/time.ts

@@ -0,0 +1,53 @@
+// HAR timing Data adapted from
+// https://github.com/exogen/node-fetch-har/blob/master/index.js
+
+import { HttpRequest } from '@envyjs/core';
+
+export type HRTime = [number, number];
+
+export type Timestamps = {
+  firstByte?: HRTime;
+  start: HRTime;
+  socket?: HRTime;
+  lookup?: HRTime;
+  connect?: HRTime;
+  received?: HRTime;
+  secureConnect?: HRTime;
+  sent?: HRTime;
+};
+
+export function calculateTiming(time: Timestamps): HttpRequest['timings'] {
+  // For backwards compatibility with HAR 1.1, the `connect` timing
+  // includes `ssl` instead of being mutually exclusive.
+  const legacyConnnect = time.secureConnect || time.connect;
+
+  const blocked = getDuration(time.start, time.socket);
+  const dns = getDuration(time.socket, time.lookup);
+  const connect = getDuration(time.lookup, legacyConnnect);
+
+  let ssl = -1;
+  if (time.secureConnect) {
+    ssl = getDuration(time.connect, time.secureConnect);
+  }
+
+  const send = getDuration(legacyConnnect, time.sent);
+  const wait = Math.max(getDuration(time.sent, time.firstByte), 0);
+  const receive = getDuration(time.firstByte, time.received);
+
+  return {
+    blocked,
+    dns,
+    connect,
+    send,
+    wait,
+    receive,
+    ssl,
+  };
+}
+
+export function getDuration(a: HRTime | undefined, b: HRTime | undefined): number {
+  if (!(a && b)) return 0;
+  const seconds = b[0] - a[0];
+  const nanoseconds = b[1] - a[1];
+  return seconds * 1000 + nanoseconds / 1e6;
+}

packages/node/src/utils/wrap.ts

@@ -0,0 +1,16 @@
+import { types as utilTypes } from 'util';
+
+import { wrap as _wrap } from 'shimmer';
+
+// ESM handling of wrapping
+export const wrap: typeof _wrap = (moduleExports, name, wrapper) => {
+  if (!utilTypes.isProxy(moduleExports)) {
+    return _wrap(moduleExports, name, wrapper);
+  } else {
+    const wrapped = _wrap(Object.assign({}, moduleExports), name, wrapper);
+
+    return Object.defineProperty(moduleExports, name, {
+      value: wrapped,
+    });
+  }
+};

packages/webui/src/components/Fields.tsx

@@ -12,20 +12,20 @@ type FieldsProps = Omit<React.HTMLAttributes<HTMLElement>, 'children'> & {
 
 export default function Fields({ className, children, ...props }: FieldsProps) {
   return (
-    <div className={tw('table table-fixed w-full', className)} {...props}>
-      <div className="table-row-group">{children}</div>
+    <div className={tw('sm:table sm:table-fixed w-full', className)} {...props}>
+      <div className="space-y-4 sm:gap-0 sm:table-row-group">{children}</div>
     </div>
   );
 }
 
 export function Field({ label, className, children, ...props }: FieldProps) {
   if (!children) return null;
   return (
-    <div className="table-row table-fixed" {...props}>
-      <div className={tw('table-cell pr-2 w-36', className)}>
+    <div className="sm:table-row sm:table-fixed" {...props}>
+      <div className={tw('sm:table-cell pr-2 w-36', className)}>
         <Label label={label} />
       </div>
-      <div className="table-cell pb-2 align-top whitespace-normal font-mono">{children}</div>
+      <div className="sm:table-cell pb-2 align-top whitespace-normal font-mono">{children}</div>
     </div>
   );
 }

packages/webui/src/components/ui/TimingsDiagram.test.tsx

@@ -0,0 +1,98 @@
+import { cleanup, render } from '@testing-library/react';
+
+import { numberFormat } from '@/utils';
+
+import TimingsDiagram from './TimingsDiagram';
+
+const timings = {
+  blocked: 10,
+  dns: 20,
+  connect: 100,
+  ssl: 70,
+  send: 30,
+  wait: 30,
+  receive: 10,
+};
+
+const timingsWithoutSsl = {
+  blocked: 10,
+  dns: 20,
+  connect: 100,
+  ssl: -1,
+  send: 30,
+  wait: 30,
+  receive: 10,
+};
+
+describe('TimingsDiagram', () => {
+  afterEach(() => {
+    cleanup();
+  });
+
+  it('should render without error', () => {
+    render(<TimingsDiagram timings={timings} />);
+  });
+
+  it('should not render anything if timings are `undefined`', () => {
+    const { container } = render(<TimingsDiagram timings={undefined} />);
+    expect(container).toBeEmptyDOMElement();
+  });
+
+  it('should not render anything if timings are `undefined`', () => {
+    const { container } = render(<TimingsDiagram timings={undefined} />);
+    expect(container).toBeEmptyDOMElement();
+  });
+
+  it('should render a row for each timing showing the correct value', () => {
+    const expectations = [
+      { label: 'Blocked', value: 10 },
+      { label: 'DNS', value: 20 },
+      { label: 'Connecting', value: 30 },
+      { label: 'TLS setup', value: 70 },
+      { label: 'Sending', value: 30 },
+      { label: 'Waiting', value: 30 },
+      { label: 'Receiving', value: 10 },
+    ];
+
+    const { getByTestId } = render(<TimingsDiagram timings={timings} />);
+    const tableBody = getByTestId('timings-table-body');
+
+    let row = tableBody.firstElementChild;
+    for (const { label, value } of expectations) {
+      if (!row) break;
+
+      const heading = row.querySelector('th');
+      const timing = row.querySelector('td');
+      expect(heading).toHaveTextContent(label);
+      expect(timing).toHaveTextContent(numberFormat(value));
+
+      row = row.nextElementSibling;
+    }
+  });
+
+  it('should render a row for each timing showing the correct value when there is no SSL involved', () => {
+    const expectations = [
+      { label: 'Blocked', value: 10 },
+      { label: 'DNS', value: 20 },
+      { label: 'Connecting', value: 100 },
+      { label: 'Sending', value: 30 },
+      { label: 'Waiting', value: 30 },
+      { label: 'Receiving', value: 10 },
+    ];
+
+    const { getByTestId } = render(<TimingsDiagram timings={timingsWithoutSsl} />);
+    const tableBody = getByTestId('timings-table-body');
+
+    let row = tableBody.firstElementChild;
+    for (const { label, value } of expectations) {
+      if (!row) break;
+
+      const heading = row.querySelector('th');
+      const timing = row.querySelector('td');
+      expect(heading).toHaveTextContent(label);
+      expect(timing).toHaveTextContent(numberFormat(value));
+
+      row = row.nextElementSibling;
+    }
+  });
+});