Merge branch 'performance-metrics'

Author: TrueWill

README.md

@@ -114,6 +114,10 @@ The `control` and the `candidate` will be run in parallel (that is, concurrently
 
 If your functions use callbacks, look at wrapping them with [util.promisify](https://nodejs.org/api/util.html#util_util_promisify_original).
 
+### Timing / profiling
+
+Published results now include timings for both the control and the candidate. Timings are in milliseconds (ms). Note that other queued tasks could affect asynchronous timings, at least in theory.
+
 ## FAQ
 
 Q. Why would I use this library?
@@ -159,10 +163,6 @@ Q. Why doesn't Tzientist randomize the order in which the control and the candid
 
 A. Because those functions should not have side effects.
 
-## To do
-
-- Timer support.
-
 ## Why
 
 GitHub's [Scientist](https://github.com/github/scientist) Ruby library is a brilliant concept. Unfortunately the Node.js alternatives aren't very TypeScript-friendly.
@@ -183,7 +183,7 @@ Feature parity with Scientist is _not_ a goal.
 ### Technology stack
 
 - TypeScript v3.8
-- Node v12 (should work on v8.17.0 or higher)
+- Node v12 (should work on v8.17.0 or higher, but tests require v12)
 - npm v6 (I like yarn, but not everyone does)
 - [Prettier](https://prettier.io/)
 - ESLint

package-lock.json

@@ -1,6 +1,6 @@
 {
   "name": "tzientist",
-  "version": "2.1.1",
+  "version": "2.2.0",
   "description": "Scientist-like library for Node.js in TypeScript",
   "main": "lib/index.js",
   "typings": "lib/index.d.ts",

package.json

@@ -54,6 +54,10 @@ describe('experiment', () => {
       expect(results.candidateResult).toBe(3);
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -101,6 +105,10 @@ describe('experiment', () => {
       expect(results.candidateResult).toBe('C');
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -149,6 +157,9 @@ describe('experiment', () => {
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeDefined();
       expect(results.candidateError.message).toBe("Candy I can't let you go");
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeUndefined();
     });
   });
 
@@ -199,6 +210,9 @@ describe('experiment', () => {
       expect(results.controlError).toBeDefined();
       expect(results.controlError.message).toBe('Kaos!');
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeUndefined();
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -250,6 +264,8 @@ describe('experiment', () => {
       expect(results.controlError.message).toBe('Kaos!');
       expect(results.candidateError).toBeDefined();
       expect(results.candidateError.message).toBe("Candy I can't let you go");
+      expect(results.controlTimeMs).toBeUndefined();
+      expect(results.candidateTimeMs).toBeUndefined();
     });
   });
 
@@ -627,6 +643,10 @@ describe('experimentAsync', () => {
       expect(results.candidateResult).toBe(3);
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -685,6 +705,10 @@ describe('experimentAsync', () => {
       expect(results.candidateResult).toBe('C');
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -743,6 +767,9 @@ describe('experimentAsync', () => {
       expect(results.controlError).toBeUndefined();
       expect(results.candidateError).toBeDefined();
       expect(results.candidateError.message).toBe("Candy I can't let you go");
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(0);
+      expect(results.candidateTimeMs).toBeUndefined();
     });
   });
 
@@ -803,6 +830,9 @@ describe('experimentAsync', () => {
       expect(results.controlError).toBeDefined();
       expect(results.controlError.message).toBe('Kaos!');
       expect(results.candidateError).toBeUndefined();
+      expect(results.controlTimeMs).toBeUndefined();
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(0);
     });
   });
 
@@ -863,6 +893,8 @@ describe('experimentAsync', () => {
       expect(results.controlError.message).toBe('Kaos!');
       expect(results.candidateError).toBeDefined();
       expect(results.candidateError.message).toBe("Candy I can't let you go");
+      expect(results.controlTimeMs).toBeUndefined();
+      expect(results.candidateTimeMs).toBeUndefined();
     });
   });
 
@@ -1051,5 +1083,30 @@ describe('experimentAsync', () => {
 
       expect(elapsedMs).toBeLessThan(msPerFunction + allowedOverhead);
     });
+
+    it('should publish individual timings', async () => {
+      const allowedVarianceMs = 125;
+      const minMs = msPerFunction - allowedVarianceMs;
+      const maxMs = msPerFunction + allowedVarianceMs;
+      const experiment = scientist.experimentAsync({
+        name: 'async parallel2',
+        control: ctrl,
+        candidate: candi,
+        options: {
+          publish: publishMock
+        }
+      });
+
+      await experiment();
+
+      expect(publishMock.mock.calls.length).toBe(1);
+      const results = publishMock.mock.calls[0][0];
+      expect(results.controlTimeMs).toBeDefined();
+      expect(results.controlTimeMs).toBeGreaterThan(minMs);
+      expect(results.controlTimeMs).toBeLessThan(maxMs);
+      expect(results.candidateTimeMs).toBeDefined();
+      expect(results.candidateTimeMs).toBeGreaterThan(minMs);
+      expect(results.candidateTimeMs).toBeLessThan(maxMs);
+    });
   });
 });

src/index.spec.ts

@@ -14,13 +14,22 @@ export interface Results<TParams extends any[], TResult> {
   candidateResult?: TResult;
   controlError?: any;
   candidateError?: any;
+  controlTimeMs?: number;
+  candidateTimeMs?: number;
 }
 
 export interface Options<TParams extends any[], TResult> {
   publish?: (results: Results<TParams, TResult>) => void;
   enabled?: (...args: TParams) => boolean;
 }
 
+function hrtimeToMs(hrtime: [number, number]): number {
+  const MS_PER_SEC = 1000;
+  const NS_PER_MS = 1e6;
+  const [seconds, nanoseconds] = hrtime;
+  return seconds * MS_PER_SEC + nanoseconds / NS_PER_MS;
+}
+
 function defaultPublish<TParams extends any[], TResult>(
   results: Results<TParams, TResult>
 ): void {
@@ -64,6 +73,8 @@ export function experiment<TParams extends any[], TResult>({
     let candidateResult: TResult | undefined;
     let controlError: any;
     let candidateError: any;
+    let controlTimeMs: number;
+    let candidateTimeMs: number;
     const isEnabled: boolean = !options.enabled || options.enabled(...args);
 
     function publishResults(): void {
@@ -74,21 +85,28 @@ export function experiment<TParams extends any[], TResult>({
           controlResult,
           candidateResult,
           controlError,
-          candidateError
+          candidateError,
+          controlTimeMs,
+          candidateTimeMs
         });
       }
     }
 
     if (isEnabled) {
       try {
+        // Not using bigint version of hrtime for Node 8 compatibility
+        const candidateStartTime = process.hrtime();
         candidateResult = candidate(...args);
+        candidateTimeMs = hrtimeToMs(process.hrtime(candidateStartTime));
       } catch (e) {
         candidateError = e;
       }
     }
 
     try {
+      const controlStartTime = process.hrtime();
       controlResult = control(...args);
+      controlTimeMs = hrtimeToMs(process.hrtime(controlStartTime));
     } catch (e) {
       controlError = e;
       publishResults();
@@ -100,6 +118,17 @@ export function experiment<TParams extends any[], TResult>({
   };
 }
 
+async function executeAndTime<TParams extends any[], TResult>(
+  controlOrCandidate: ExperimentAsyncFunction<TParams, TResult>,
+  args: TParams
+): Promise<[TResult, number]> {
+  // Not using bigint version of hrtime for Node 8 compatibility
+  const startTime = process.hrtime();
+  const result = await controlOrCandidate(...args);
+  const timeMs = hrtimeToMs(process.hrtime(startTime));
+  return [result, timeMs];
+}
+
 /**
  * A factory that creates an asynchronous experiment function.
  *
@@ -127,6 +156,8 @@ export function experimentAsync<TParams extends any[], TResult>({
     let candidateResult: TResult | undefined;
     let controlError: any;
     let candidateError: any;
+    let controlTimeMs: number | undefined;
+    let candidateTimeMs: number | undefined;
     const isEnabled: boolean = !options.enabled || options.enabled(...args);
 
     function publishResults(): void {
@@ -137,21 +168,26 @@ export function experimentAsync<TParams extends any[], TResult>({
           controlResult,
           candidateResult,
           controlError,
-          candidateError
+          candidateError,
+          controlTimeMs,
+          candidateTimeMs
         });
       }
     }
 
     if (isEnabled) {
       // Run in parallel
-      [candidateResult, controlResult] = await Promise.all([
-        candidate(...args).catch((e) => {
+      [
+        [candidateResult, candidateTimeMs],
+        [controlResult, controlTimeMs]
+      ] = await Promise.all([
+        executeAndTime(candidate, args).catch((e) => {
           candidateError = e;
-          return undefined;
+          return [undefined, undefined];
         }),
-        control(...args).catch((e) => {
+        executeAndTime(control, args).catch((e) => {
           controlError = e;
-          return undefined;
+          return [undefined, undefined];
         })
       ]);
     } else {