Repository: elastic/synthetics (ts)

Issue:
Mysterious overhead being added between journey start/stop and step start/stop
The `monitor.duration` in the heartbeat summary is calculated based purely on the differences of times between the `journey/start` and `journey/end` events. See https://github.com/elastic/beats/blob/master/x-pack/heartbeat/monitors/browser/synthexec/enrich.go#L167 for the implementation.

In the real world we extra time accounted for between journey start/stop and step start/end events. We should figure out why.

Running a simple journey locally I see:

```
# elastic-synthetics . --match "check if title is present" --reporter json --screenshots off | jq '{t: .type, ts: ."@timestamp"}'
{
  "t": "synthetics/metadata",
  "ts": 1636138571717791.8 // T=-0.282s
}
{
  "t": "journey/start",
  "ts": 1636138572000137.5 // T=0s
}
{
  "t": "step/end",
  "ts": 1636138572231909.8 // T=0.23s
}
{
  "t": "step/end",
  "ts": 1636138572265338.5 // T=0.26s
}
{
  "t": "journey/end",
  "ts": 1636138572265777.2 // T=0.265s
}
```

So, I'm seeing a total of `0.235s` time added as overhead.

Pull request:
fix: end timestamp should reflect duration
+ fix #409 

### Problem
Heartbeat monitor calculation is based on the event.timestamp field for journey start and journey end event. Synthetic agent journey/end timestamp is calculated after post processing of the screenshots and network events being written to the JSON output. As a result, Step duration and Monitor duration timings would be hugely different as we are accounting for all the CPU heavy work that comes to extracting and chopping screenshots. 

### Solution

We use the timestamp during journey end and don't account for the time taken for the post processing of other work that synthetics agent is doing under the hood. 

Patch:
diff --git a/src/core/gatherer.ts b/src/core/gatherer.ts
index 51b15ea..b73c9ed 100644
--- a/src/core/gatherer.ts
+++ b/src/core/gatherer.ts
@@ -37,6 +37,7 @@ export class Gatherer {
   static browser: ChromiumBrowser;
 
   static async setupDriver(options: RunOptions): Promise<Driver> {
+    log('Gatherer: setup driver');
     const { wsEndpoint, playwrightOptions, networkConditions } = options;
 
     if (Gatherer.browser == null) {
diff --git a/src/core/runner.ts b/src/core/runner.ts
index c9e9354..93a2838 100644
--- a/src/core/runner.ts
+++ b/src/core/runner.ts
@@ -123,6 +123,7 @@ interface Events {
     JourneyResult & {
       journey: Journey;
       options: RunOptions;
+      timestamp: number;
     };
   'journey:end:reported': unknown;
   'step:start': { journey: Journey; step: Step };
@@ -149,8 +150,12 @@ export default class Runner extends EventEmitter {
   static screenshotPath = join(CACHE_PATH, 'screenshots');
 
   static async createContext(options: RunOptions): Promise<JourneyContext> {
-    const start = monotonicTimeInSeconds();
     const driver = await Gatherer.setupDriver(options);
+    /**
+     * Do not include browser launch/context creation duration
+     * as part of journey duration
+     */
+    const start = monotonicTimeInSeconds();
     const pluginManager = await Gatherer.beginRecording(driver, options);
     /**
      * For each journey we create the screenshots folder for
@@ -339,6 +344,7 @@ export default class Runner extends EventEmitter {
     result: JourneyContext & JourneyResult,
     options: RunOptions
   ) {
+    const end = monotonicTimeInSeconds();
     const { pluginManager, start, status, error } = result;
     const pluginOutput = pluginManager.output();
     this.emit('journey:end', {
@@ -346,7 +352,8 @@ export default class Runner extends EventEmitter {
       status,
       error,
       start,
-      end: monotonicTimeInSeconds(),
+      end,
+      timestamp: getTimestamp(),
       options,
       ...pluginOutput,
       browserconsole: status == 'failed' ? pluginOutput.browserconsole : [],
@@ -378,6 +385,7 @@ export default class Runner extends EventEmitter {
     };
     this.emit('journey:end', {
       journey,
+      timestamp: getTimestamp(),
       start,
       options,
       end: monotonicTimeInSeconds(),
@@ -393,8 +401,8 @@ export default class Runner extends EventEmitter {
     const result: JourneyResult = {
       status: 'succeeded',
     };
-    log(`Runner: start journey (${journey.name})`);
     const context = await Runner.createContext(options);
+    log(`Runner: start journey (${journey.name})`);
     try {
       this.registerJourney(journey, context);
       const hookArgs = {
diff --git a/src/reporters/json.ts b/src/reporters/json.ts
index 1dfa277..e484499 100644
--- a/src/reporters/json.ts
+++ b/src/reporters/json.ts
@@ -435,6 +435,7 @@ export default class JSONReporter extends BaseReporter {
       'journey:end',
       async ({
         journey,
+        timestamp,
         start,
         end,
         networkinfo,
@@ -501,6 +502,7 @@ export default class JSONReporter extends BaseReporter {
         this.writeJSON({
           type: 'journey/end',
           journey,
+          timestamp,
           error,
           payload: {
             start,


Test patch:
diff --git a/__tests__/reporters/base.test.ts b/__tests__/reporters/base.test.ts
index da871d1..dce4eed 100644
--- a/__tests__/reporters/base.test.ts
+++ b/__tests__/reporters/base.test.ts
@@ -102,6 +102,7 @@ describe('base reporter', () => {
     };
     runner.emit('journey:end', {
       journey: j1,
+      timestamp,
       status: 'failed',
       error,
       start: 0,
diff --git a/__tests__/reporters/json.test.ts b/__tests__/reporters/json.test.ts
index 49fd3ca..adade9d 100644
--- a/__tests__/reporters/json.test.ts
+++ b/__tests__/reporters/json.test.ts
@@ -163,6 +163,7 @@ describe('json reporter', () => {
     });
     runner.emit('journey:end', {
       journey: j1,
+      timestamp,
       status: 'succeeded',
       start: 0,
       end: 11,
@@ -225,6 +226,7 @@ describe('json reporter', () => {
 
     runner.emit('journey:end', {
       journey: j1,
+      timestamp,
       start: 0,
       end: 1,
       status: 'failed',
@@ -242,6 +244,7 @@ describe('json reporter', () => {
     const journeyOpts = { name: 'name', id: 'id', tags: ['tag1', 'tag2'] };
     runner.emit('journey:end', {
       journey: journey(journeyOpts, () => {}),
+      timestamp,
       start: 0,
       end: 1,
       status: 'skipped',
@@ -301,6 +304,7 @@ describe('json reporter', () => {
     const emitEnd = (options, status = 'failed' as StatusValue) =>
       runner.emit('journey:end', {
         journey: j1,
+        timestamp,
         start: 0,
         status,
         options,
diff --git a/__tests__/reporters/junit.test.ts b/__tests__/reporters/junit.test.ts
index 375c3a4..8ce7d0a 100644
--- a/__tests__/reporters/junit.test.ts
+++ b/__tests__/reporters/junit.test.ts
@@ -81,6 +81,7 @@ describe('junit reporter', () => {
     });
     runner.emit('journey:end', {
       journey: j1,
+      timestamp,
       start: 0,
       status: 'failed',
       options: {},
@@ -115,6 +116,7 @@ describe('junit reporter', () => {
     });
     runner.emit('journey:end', {
       journey: j1,
+      timestamp,
       start: 0,
       status: 'failed',
       options: {},