Default reporter emits prepare longer than Duration when prepare takes longer than 1s

[jhonnymoreira]

Describe the bug

When greater than 1s, the prepare field on Duration seems to report the wrong time. The example test (reproduction section) didn't last 34s.

---

Example - StackBlitz

 Test Files  13 passed | 59 skipped (72)
      Tests  36 passed (36)
   Start at  00:16:31
   Duration  18.80s (transform 1.11s, setup 6ms, collect 1.61s, tests 60ms, environment 21ms, prepare 34.16s)

Example - Local

 Test Files  13 passed | 59 skipped (72)
      Tests  36 passed (36)
   Start at  00:09:35
   Duration  4.84s (transform 1.58s, setup 12ms, collect 2.54s, tests 177ms, environment 37ms, prepare 31.93s)

Reproduction

Run pnpm test on the following StackBlitz example:

https://stackblitz.com/~/github.com/jhonnymoreira/leetcode-dsa-crash-course-ts

System Info - StackBlitz

  System:
    OS: Linux 5.0 undefined
    CPU: (8) x64 Intel(R) Core(TM) i9-9880H CPU @ 2.30GHz
    Memory: 0 Bytes / 0 Bytes
    Shell: 1.0 - /bin/jsh
  Binaries:
    Node: 18.18.0 - /usr/local/bin/node
    Yarn: 1.22.19 - /usr/local/bin/yarn
    npm: 10.2.3 - /usr/local/bin/npm
    pnpm: 8.15.6 - /usr/local/bin/pnpm
  npmPackages:
    vite: latest => 5.2.11 
    vitest: latest => 1.6.0

System Info - Local

  System:
    OS: Linux 5.15 Ubuntu 22.04.4 LTS 22.04.4 LTS (Jammy Jellyfish)
    CPU: (24) x64 AMD Ryzen 9 5900X 12-Core Processor
    Memory: 12.49 GB / 15.57 GB
    Container: Yes
    Shell: 5.8.1 - /usr/bin/zsh
  Binaries:
    Node: 20.11.0 - ~/.nvm/versions/node/v20.11.0/bin/node
    npm: 10.3.0 - ~/.nvm/versions/node/v20.11.0/bin/npm
    pnpm: 9.1.1 - ~/.nvm/versions/node/v20.11.0/bin/pnpm
  npmPackages:
    @vitest/coverage-v8: ^1.6.0 => 1.6.0 
    vitest: ^1.6.0 => 1.6.0 

Used Package Manager

• StackBlitz: npm
• Local: pnpm

Validations

• Follow our Code of Conduct
• Read the Contributing Guidelines.
• Read the docs.
• Check that there isn't already an issue that reports the same bug to avoid creating a duplicate.
• Check that this is a concrete bug. For Q&A open a GitHub Discussion or join our Discord Chat Server.
• The provided reproduction is a minimal reproducible example of the bug.

[sheremet-va]

It's absolutely normal to have times after duration be higher than duration since they are aggregated across all test file which are loaded in parallel.

What is not normal is how high the number is 🤔

[sheremet-va]

What is not normal is how high the number is 🤔

After investigation, I didn't find anything unexpected. When running a single test, prepare time is faster than if running multiple in parallel, and you have a lot of files without a test inside, so we basically run a lot of files for nothing which inflates the number.

Also, looking at your project I would recommend disabling isolation with --no-isolate to drastically speed up your tests (prepare state would be very minimal since we only need to run it once and can cache it for every test)

[jhonnymoreira]

@sheremet-va, thanks for looking into the "issue" and explaining how it works internally. I'll try the option you mentioned. ;)

Have a great week!

---

Edit

The test duration was drastically reduced. Thank you!

 Test Files  17 passed | 55 skipped (72)
      Tests  48 passed (48)
   Start at  14:04:04
   Duration  1.51s (transform 2.02s, setup 5ms, collect 2.94s, tests 80ms, environment 10ms, prepare 10.41s)