feat: measure startup delay and journey duration (#709)

* feat: measure startup delay and journey duration * fix test * move it under payload
elastic · Jul 15, 2024 · 2de3bce · 2de3bce
1 parent 686f95a
commit 2de3bce
Show file tree

Hide file tree

Showing 9 changed files with 63 additions and 21 deletions.
diff --git a/__tests__/reporters/__snapshots__/json.test.ts.snap b/__tests__/reporters/__snapshots__/json.test.ts.snap
@@ -195,7 +195,7 @@ exports[`json reporter screenshots write block & reference docs 1`] = `
 {"type":"screenshot/block","_id":"e89af7cc2cae152df54ccf091793db64b3dfe995","@timestamp":1600300800000000,"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"blob":"/9j/2wBDAAYEBQYFBAYGBQYHBwYIChAKCgkJChQODwwQFxQYGBcUFhYaHSUfGhsjHBYWICwgIyYnKSopGR8tMC0oMCUoKSj/2wBDAQcHBwoIChMKChMoGhYaKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCj/wAARCABaAKADASIAAhEBAxEB/8QAFQABAQAAAAAAAAAAAAAAAAAAAAj/xAAUEAEAAAAAAAAAAAAAAAAAAAAA/8QAFAEBAAAAAAAAAAAAAAAAAAAAAP/EABQRAQAAAAAAAAAAAAAAAAAAAAD/2gAMAwEAAhEDEQA/AKcAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAB//9k=","blob_mime":"image/jpeg","package_version":"0.0.1"}
 {"type":"screenshot/block","_id":"e89af7cc2cae152df54ccf091793db64b3dfe995","@timestamp":1600300800000000,"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"blob":"/9j/2wBDAAYEBQYFBAYGBQYHBwYIChAKCgkJChQODwwQFxQYGBcUFhYaHSUfGhsjHBYWICwgIyYnKSopGR8tMC0oMCUoKSj/2wBDAQcHBwoIChMKChMoGhYaKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCgoKCj/wAARCABaAKADASIAAhEBAxEB/8QAFQABAQAAAAAAAAAAAAAAAAAAAAj/xAAUEAEAAAAAAAAAAAAAAAAAAAAA/8QAFAEBAAAAAAAAAAAAAAAAAAAAAP/EABQRAQAAAAAAAAAAAAAAAAAAAAD/2gAMAwEAAhEDEQA/AKcAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAB//9k=","blob_mime":"image/jpeg","package_version":"0.0.1"}
 {"type":"step/screenshot_ref","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"launch app","index":1},"root_fields":{"screenshot_ref":{"width":1280,"height":720,"blocks":[{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":320,"width":160,"height":90},{"hash":"7207d2da8fc8a9423ea2e38501061ba30dca2e49","top":0,"left":480,"width":160,"height":90},{"hash":"c895742d0c552bb1e90bb9054dce0a207e0612f4","top":0,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":0,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":160,"width":160,"height":90},{"hash":"8dab22ef3ba33256e102c7755d6d05309d447a5d","top":90,"left":320,"width":160,"height":90},{"hash":"0503e01e69b834685b61bb12b897189f70b7f8cf","top":90,"left":480,"width":160,"height":90},{"hash":"1e2e95c527b7911704f108caa2dc124b71a6906c","top":90,"left":640,"width":160,"height":90},{"hash":"6bb91d0bcccfe17810c585ff9676da9bf060e7ea","top":90,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":90,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":160,"width":160,"height":90},{"hash":"4bef2a34c082065f7fd8a9246be3b82265640151","top":180,"left":320,"width":160,"height":90},{"hash":"166035c43b7ec64602a23cecb800d72d07a8fd07","top":180,"left":480,"width":160,"height":90},{"hash":"5da56b5b7ff6d979000b0e6c3e5047a07eb746a9","top":180,"left":640,"width":160,"height":90},{"hash":"2cd55289e3819c419182ad42af7b0e017ef252ec","top":180,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":180,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":320,"width":160,"height":90},{"hash":"fead29b7726776d52be4fa448f1e0c603f89ea21","top":270,"left":480,"width":160,"height":90},{"hash":"07b755d38bae03aac9cfd6c0f10d98387d81026d","top":270,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":270,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":360,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":450,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":540,"left":1120,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":0,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":160,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":320,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":480,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":640,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":800,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":960,"width":160,"height":90},{"hash":"e89af7cc2cae152df54ccf091793db64b3dfe995","top":630,"left":1120,"width":160,"height":90}]},"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"package_version":"0.0.1"}
-{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"failed"},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"start":0,"end":2,"status":"failed"},"package_version":"0.0.1"}
+{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"failed","duration":{"us":2000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"status":"failed","browser_delay_us":0,"process_startup_epoch_us":1600300800000000},"package_version":"0.0.1"}
 "
 `;
 
@@ -210,6 +210,6 @@ exports[`json reporter writes each step as NDJSON to the FD 1`] = `
 {"type":"step/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"s1","index":1,"status":"succeeded","duration":{"us":10000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"source":"function noop() { }","url":"dummy","status":"succeeded"},"url":"dummy","package_version":"0.0.1"}
 {"type":"journey/network_info","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"root_fields":{"user_agent":{},"http":{"request":{}},"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"browser":{},"is_navigation_request":true},"package_version":"0.0.1"}
 {"type":"journey/browserconsole","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1"},"step":{"name":"step-name","index":0},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"text":"Boom","type":"error"},"package_version":"0.0.1"}
-{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"succeeded"},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"start":0,"end":11,"status":"succeeded"},"package_version":"0.0.1"}
+{"type":"journey/end","@timestamp":1600300800000000,"journey":{"name":"j1","id":"j1","status":"succeeded","duration":{"us":11000000}},"root_fields":{"os":{"platform":"darwin"},"package":{"name":"@elastic/synthetics","version":"0.0.1"}},"payload":{"status":"succeeded","browser_delay_us":2000000,"process_startup_epoch_us":1600300800000000},"package_version":"0.0.1"}
 "
 `;
diff --git a/__tests__/reporters/base.test.ts b/__tests__/reporters/base.test.ts
@@ -92,6 +92,7 @@ describe('base reporter', () => {
       error,
       start: 0,
       end: 1,
+      browserDelay: 0,
       options: {},
     });
     reporter.onEnd();

diff --git a/__tests__/reporters/buildkite-cli.test.ts b/__tests__/reporters/buildkite-cli.test.ts
@@ -39,7 +39,7 @@ describe('buildkite cli reporter', () => {
   let stream: SonicBoom;
   let reporter: BuildKiteCLIReporter;
   const timestamp = 1600300800000000;
-  const j1 = journey('j1', () => {});
+  const j1 = journey('j1', () => { });
 
   const readAndCloseStream = async () => {
     /**
@@ -90,6 +90,7 @@ describe('buildkite cli reporter', () => {
       },
       start: 0,
       end: 1,
+      browserDelay: 0,
       options: {},
     });
     reporter.onEnd();
@@ -111,6 +112,7 @@ describe('buildkite cli reporter', () => {
       error,
       start: 0,
       end: 1,
+      browserDelay: 0,
       options: {},
     });
     reporter.onEnd();
@@ -138,6 +140,7 @@ describe('buildkite cli reporter', () => {
       status: 'succeeded',
       start: 4,
       end: 6,
+      browserDelay: 0,
       options: {},
     });
     reporter.onEnd();

diff --git a/__tests__/reporters/json.test.ts b/__tests__/reporters/json.test.ts
@@ -48,9 +48,18 @@ jest.mock(
   jest.fn(() => ({ version: '0.0.1', name: '@elastic/synthetics' }))
 );
 
+/**
+ * Mock the timeOrigin to log process startup time
+ */
+jest.mock('perf_hooks', () => ({
+  performance: {
+    timeOrigin: 1600300800000,
+  },
+}));
+
 describe('json reporter', () => {
   let dest: string;
-  const j1 = journey('j1', () => {});
+  const j1 = journey('j1', () => { });
   let stream: SonicBoom;
   let reporter: JSONReporter;
   const timestamp = 1600300800000000;
@@ -160,6 +169,7 @@ describe('json reporter', () => {
       status: 'succeeded',
       start: 0,
       end: 11,
+      browserDelay: 2,
       options: {},
       networkinfo: [
         {
@@ -238,6 +248,7 @@ describe('json reporter', () => {
       timestamp,
       start: 0,
       end: 1,
+      browserDelay: 0,
       status: 'failed',
       error: myErr,
       options: {},
@@ -254,6 +265,7 @@ describe('json reporter', () => {
       timestamp,
       start: 0,
       end: 1,
+      browserDelay: 0,
       status: 'failed',
       error: 'boom' as any,
       options: {},
@@ -269,11 +281,12 @@ describe('json reporter', () => {
     const journeyOpts = { name: 'name', id: 'id', tags: ['tag1', 'tag2'] };
 
     reporter.onJourneyEnd(
-      journey(journeyOpts, () => {}),
+      journey(journeyOpts, () => { }),
       {
         timestamp,
         start: 0,
         end: 1,
+        browserDelay: 0,
         status: 'skipped',
         options: {},
       }
@@ -282,7 +295,11 @@ describe('json reporter', () => {
     const journeyEnd = (await readAndCloseStreamJson()).find(
       json => json.type == 'journey/end'
     );
-    expect(journeyEnd.journey).toEqual({ ...journeyOpts, status: 'skipped' });
+    expect(journeyEnd.journey).toEqual({
+      ...journeyOpts,
+      duration: { us: 1 * 1e6 },
+      status: 'skipped',
+    });
   });
 
   it('captures number of journeys as metadata event', async () => {
@@ -331,6 +348,7 @@ describe('json reporter', () => {
       reporter.onJourneyEnd(j1, {
         timestamp,
         start: 0,
+        browserDelay: 0,
         end: 2,
         status,
         options,

diff --git a/__tests__/reporters/junit.test.ts b/__tests__/reporters/junit.test.ts
@@ -70,6 +70,7 @@ describe('junit reporter', () => {
       timestamp,
       start: 0,
       end: 2,
+      browserDelay: 0,
       status: 'failed',
       options: {},
     });
@@ -98,6 +99,7 @@ describe('junit reporter', () => {
       timestamp,
       start: 0,
       end: 2,
+      browserDelay: 0,
       status: 'failed',
       options: {},
     });

diff --git a/src/common_types.ts b/src/common_types.ts
@@ -323,6 +323,7 @@ export type JourneyEndResult = JourneyStartResult &
   JourneyResult & {
     start: number;
     end: number;
+    browserDelay: number;
     options: RunOptions;
     timestamp: number;
   };

diff --git a/src/core/runner.ts b/src/core/runner.ts
@@ -60,6 +60,7 @@ export type SuiteHooks = Record<HookType, Array<HooksCallback>>;
 
 type JourneyContext = {
   params?: Params;
+  browserDelay: number;
   start: number;
   driver: Driver;
   pluginManager: PluginManager;
@@ -78,6 +79,7 @@ export default class Runner {
   static screenshotPath = join(CACHE_PATH, 'screenshots');
 
   static async createContext(options: RunOptions): Promise<JourneyContext> {
+    const browserStart = monotonicTimeInSeconds();
     const driver = await Gatherer.setupDriver(options);
     /**
      * Do not include browser launch/context creation duration
@@ -92,6 +94,7 @@ export default class Runner {
     await mkdir(this.screenshotPath, { recursive: true });
     return {
       start,
+      browserDelay: start - browserStart,
       params: options.params,
       driver,
       pluginManager,
@@ -314,13 +317,14 @@ export default class Runner {
     options: RunOptions
   ) {
     const end = monotonicTimeInSeconds();
-    const { pluginManager, start, status, error } = result;
+    const { pluginManager, start, status, error, browserDelay } = result;
     const pluginOutput = await pluginManager.output();
     await this.#reporter?.onJourneyEnd?.(journey, {
       status,
       error,
       start,
       end,
+      browserDelay,
       timestamp: getTimestamp(),
       options,
       ...pluginOutput,
@@ -350,6 +354,7 @@ export default class Runner {
       timestamp: getTimestamp(),
       start,
       options,
+      browserDelay: 0,
       end: monotonicTimeInSeconds(),
       ...result,
     });

diff --git a/src/helpers.ts b/src/helpers.ts
@@ -95,7 +95,7 @@ export function microSecsToSeconds(ts: number) {
 /**
  * Timestamp at which the current node process began.
  */
-const processStart = performance.timeOrigin;
+export const processStart = performance.timeOrigin;
 export function getTimestamp() {
   return (processStart + now()) * 1000;
 }

diff --git a/src/reporters/json.ts b/src/reporters/json.ts
@@ -35,6 +35,7 @@ import {
   totalist,
   isDirectory,
   getDurationInUs,
+  processStart,
 } from '../helpers';
 import { Journey, Step } from '../dsl';
 import snakeCaseKeys from 'snakecase-keys';
@@ -73,9 +74,9 @@ type OutputType =
 
 type Payload = {
   source?: string;
-  start?: number;
-  end?: number;
   url?: string;
+  browser_delay_us?: number;
+  process_startup_epoch_us?: number;
   status?: StatusValue;
   pagemetrics?: PageMetrics;
   type?: OutputType;
@@ -84,17 +85,19 @@ type Payload = {
   network_conditions?: NetworkConditions;
 };
 
+type Duration = {
+  duration?: {
+    us: number;
+  };
+};
+
 type OutputFields = {
   type: OutputType;
   _id?: string;
-  journey?: Journey;
+  journey?: Partial<Journey> & Duration;
   timestamp?: number;
   url?: string;
-  step?: Partial<Step> & {
-    duration?: {
-      us: number;
-    };
-  };
+  step?: Partial<Step> & Duration;
   error?: Error;
   root_fields?: Record<string, unknown>;
   payload?: Payload;
@@ -260,6 +263,7 @@ function journeyInfo(
     id: journey.id,
     tags: journey.tags,
     status: type === 'journey/end' ? status : undefined,
+    duration: journey.duration,
   };
 }
 
@@ -369,8 +373,8 @@ export default class JSONReporter extends BaseReporter {
       },
       payload: event.networkConditions
         ? {
-            network_conditions: event.networkConditions,
-          }
+          network_conditions: event.networkConditions,
+        }
         : undefined,
     });
   }
@@ -451,6 +455,7 @@ export default class JSONReporter extends BaseReporter {
       timestamp,
       start,
       end,
+      browserDelay,
       networkinfo,
       browserconsole,
       status,
@@ -517,13 +522,20 @@ export default class JSONReporter extends BaseReporter {
 
     this.writeJSON({
       type: 'journey/end',
-      journey,
+      journey: {
+        ...journey,
+        duration: {
+          us: getDurationInUs(end - start),
+        },
+      },
       timestamp,
       error,
       payload: {
-        start,
-        end,
         status,
+        // convert from monotonic seconds time to microseconds
+        browser_delay_us: getDurationInUs(browserDelay),
+        // timestamp in microseconds at which the current node process began, measured in Unix time.
+        process_startup_epoch_us: Math.trunc(processStart * 1000),
       },
     });
   }