[Feature]: Add `endTime` to `TestResult`

[cpAdm]

🚀 Feature Request

Add endTime property to TestResult which would be the end time of this particular test run.

(and probably add it to TestStep as well)

Example

No response

Motivation

Currently testResult.startTime + testResult.duration is smaller than the actual end time. So computing the end time from these two properties is not accurate.

In our use case, we need a more accurate timestamp because we match server logs to a specific test based on time.

Test showing this behaviour

test('should approximate end time from with startTime + duration', async ({ runInlineTest }) => {
  const result = await runInlineTest({
    'reporter.ts': `
      class Reporter {
        onTestEnd(test, result) {
          console.log('%%start=' + result.startTime.getTime());
          console.log('%%duration=' + result.duration);
        }
        onStdOut(data) {
          // forward test stdout so %%actualEndTest lines reach outputLines
          process.stdout.write(data.toString());
        }
      }
      module.exports = Reporter;
    `,
    'playwright.config.ts': `module.exports = { reporter: './reporter' };`,
    'a.spec.ts': `
      import { test } from '@playwright/test';
      test('timing', async () => {
        await new Promise(f => setTimeout(f, 250));
        console.log('%%actualEndTest=' + Date.now());
      });
    `,
  }, { reporter: '', workers: 1 });

  const start = Number(result.outputLines.find(l => l.startsWith('start='))!.split('=')[1]);
  const duration = Number(result.outputLines.find(l => l.startsWith('duration='))!.split('=')[1]);
  const actualEndTest = Number(result.outputLines.find(l => l.startsWith('actualEndTest='))!.split('=')[1]);

  const reportedTestEnd = start + duration;
  const delta = actualEndTest - reportedTestEnd;
  const dateToTime = (ms: number) => new Date(ms).toISOString().slice(11, 23); // HH:MM:SS.mmm
  console.log([
    `start\t\t${dateToTime(start)}`,
    `reportedEnd\t${dateToTime(reportedTestEnd)}`,
    `actualEnd\t${dateToTime(actualEndTest)}`,
    `durationMs\t${duration} ms`,
    `deltaMs\t\t${delta} ms`,
  ].join('\n'));
});

Relative: #38604

[pavelfeldman]

Currently testResult.startTime + testResult.duration is smaller than the actual end time. So computing the end time from these two properties is not accurate.

what will endTime include that start + duration does not cover?

[cpAdm]

what will endTime include that start + duration does not cover?

Well maybe it is actually a bug with duration (I have not yet looked deep in the playwright code), but testResult.startTime + testResult.duration should definetely be equal or large than actualEndTest in above example.

[dgozman]

@cpAdm duration does not include things like beforeAll hooks or worker-scoped fixtures. Unfortunately, there is no good solution here - we want to both keep duration only include test-specific timings, but that does not necessary aligns with calling Date.now() in various places of the test.

[cpAdm]

@dgozman Tricky. Maybe lets keep duration as is (for backwards compatibility), but add endTime which more closely reflects the actual end time?

[dgozman]

@cpAdm Well, that would raise questions of why startTime + duration !== endTime 😄

For your usecase, could you consider everything between two consecutive startTime values as belonging to the first test?

[cpAdm]

@dgozman Fair point, although one could document why this is the case.

It's a bit more tricky, since all tests run in parallel (so matching the logs isn't one-to-one to begin with). But I guess we could use parallelIndex to find the right next test for the current worker.

(Currently we don't shard tests so missing shardIndex #38962, is not an issue.)