[Bug]: Report's total time is incorrect

[pauleustice]

Version

1.43.0

Steps to reproduce

• Generate an HTML report
• Observe that the cumulative individual times for the listed tests do not match the "Total time" text
• Secondary issue: observe that the stated times for individual tests do not reflect before/after hook times
  • Compare the time at the top of a test's page (?testId=) to the total time of the "Test Steps" below

In order to calculate the real total time, one can run the following script in the console. I have also manually performed a total on a report (for a suite where all tests completed in seconds) to ensure that my script is behaving correctly.

---

Totaliser script

// Run this on a Playwright report to change display durations in seconds
// and console log the total of all those values (which seems to exclude hooks)
// in minutes and seconds

const tests = {
  m: [],
  s: [],
  ms: [],
};

const sortFn = (a, b) => {
  if (a.duration < b.duration) {
    return 1
  } else if (a.duration > b.duration) {
    return -1
  } else {
    return 0;
  }
}

document.querySelectorAll('.test-file-test').forEach(e => {
  const duration = e.querySelector('[data-testid=test-duration]').innerText;
  const unit = duration.match(/[a-z]+$/)[0];

  tests[unit].push({
    e,
    duration: Number(duration.slice(0, -unit.length)),
  });
});

let total = 0;

Object.keys(tests).forEach(unit => {
  tests[unit].sort(sortFn);

  tests[unit].forEach(t => {
    if (unit === 'm') {
      t.e.querySelector('[data-testid=test-duration]').innerText = `${t.duration * 60}s`;
      total += t.duration * 60;
    } else if (unit === 's') {
      total += t.duration;
    }
  });
});

const totalMins = total / 60;
const totalMinsInt = parseInt(totalMins);
const totalMinsFraction = (totalMins % 1).toFixed(3);
const fractionInSeconds = (totalMinsFraction * 60).toFixed(0);
const totalFormattedTime = `${totalMinsInt}m ${fractionInSeconds}s`;

console.info('total duration in minutes', totalMins);
console.info('seconds', totalMinsFraction * 60);
console.info('totalTime', totalFormattedTime);

The script will convert the display values into seconds (for easier manual totalling) and log out the total in a minutes and seconds format.

Examples:

Expected behavior

Total time

The "Total time" is equivalent to the total of all the individual test times below it

Individual test time

The total time for a given test includes the before/after hook time too

Actual behavior

Total time

Sometimes the reported total (the one at the top of the report) is higher than the real total. For others it is lower. The degree to which it differs also varies; I have observed a delta of double the actual total.

Some observed differences

Reported total	Actual total
17.2m	18m 58s
11.1m	5m 4s
11.4m	12m 5s

[!NOTE] I cannot say whether this occurs for all reports, but I have certainly observed it on several within the repo I'm working on at the moment

Individual test time

It does not include the Before Hooks or After Hooks durations

Additional context

No response

Environment

System:
    OS: macOS 14.3
    CPU: (8) arm64 Apple M1 Pro
    Memory: 51.83 MB / 32.00 GB
  Binaries:
    Node: 18.10.0 - ~/.nvm/versions/node/v18.10.0/bin/node
    Yarn: 1.22.21 - /opt/homebrew/bin/yarn
    npm: 8.19.2 - ~/.nvm/versions/node/v18.10.0/bin/npm
  Languages:
    Bash: 3.2.57 - /bin/bash
  npmPackages:
    @playwright/test: ^1.43.0 => 1.43.0

[pauleustice]

It's worth mentioning that for the second issue of before/after hooks not being included in the times, it is useful to be able to see the times as they are currently. Indeed this choice/bug/feature helped me debug a long standing issue, so I am grateful :)

However, I think the ability to either toggle, or show the times separately, would be useful as it is misleading

[mxschmitt]

Would it be possible to share a reproduction with us? Ideally something we can run locally.

[pauleustice]

Would it be possible to share a reproduction with us? Ideally something we can run locally.

I wouldn't be able to share our test suite as it's confidential and we're in financial services, but I'll try to find an example repo somewhere that generates a report with the issue. I believe it'll apply to any repo/report though

[yury-s]

The "Total time" is equivalent to the total of all the individual test times below it

"Total time:" in the top right corner of the report shows wall time of running npx playwright test, the actual "CPU" time for running all tests could be more due to the tests running in parallel. You can see total "CPU" time for subset of tests when filtering them:

Secondary issue: observe that the stated times for individual tests do not reflect before/after hook times

They only include test time that accounts toward total test time and compared against test timeout in the config. It means that it will include before/afterEach hooks and test itself, but won't include time spent in before/afterAll hooks and worker fixtures. We could probably do better job showing which of the times from Before/After Hooks is attributed to the test itself.

[pauleustice]

Thanks for the reply @yury-s, that seems to explain it and I've just validated that against the test reports that I have here.

Can I suggest that this is updated to show both figures (CPU and elapsed)? The total time is very useful for debugging performance issues between tests and runs, but is currently really misleading. That's what led me to realise the discrepancy.

Likewise with not showing the before/after hook times - we are facing an issue where the afterAll hook is slowing down our tests but it wasn't immediately clear. A 5 second test was delayed by a 2 minute afterAll hook, which wasn't apparent from the report's main page.

Should I submit these suggestions as a separate feature request?

[Jamesj001]

@yury-s is there way to get this data meaning time spent in internal process and by whom Currently if I generate a junit report for a single test case run I see test case runtime as lets say ~0.799 seconds but overall testsuites time is ~19.698 seconds

So its hard to understand where actually that time went in to understand is there any performance improvement we could achieve from consumer's end or is this time consumption purely from PW's end

"Total time:" in the top right corner of the report shows wall time of running npx playwright test, the actual "CPU" time for running all tests could be more due to the tests running in parallel

Also just a note I'm doing component testing so I'm assuming that building components step also contributes to testSuites time please feel free to correct me if wrong here since building components is also taking only 9-10 seconds only so not sure from where this additional 19.698 - (10 (building component time)+ 0.799 (test execution time)) = ~8.899 seconds is coming from