[BUG] Performance degradation when large number of assertions is checked at once, with non-silent reporter

[inga-lovinde]

Is there an existing issue for this?

• I have searched the existing issues

Have you read the CONTRIBUTING guide on posting bugs, and CODE_OF_CONDUCT?

• yes I read the things

This issue exists in the latest tap version

• I am using the latest tap

Description

When a lot of small tests and assertions are run from several different files, tap is really slow (13 seconds for 25k simple assertions in 25k simple tests in five test files, as in example below).
Running tap with --reporter=silent improves performance by 2.5x.

(With real-world tests the difference might be even more noticeable. I've noticed this problem when my tests (~200k assertions in 20 files) were taking 70+ seconds; running them with --reporter=terse only reduced the runtime to 40 seconds; but running them with --reporter=min or --reporter=silent reduced the runtime to 12 seconds, the difference of 6x. Unfortunately I was unable to come up with a simple reproduction case demonstrating more than 2.5x difference.)

I would expect tap to take similar (small) amount of time for both the default reporter and silent reporter.

Reproduction

I have the following perf.ts file:

import t from "tap";

const waitForTick = () => new Promise(resolve => setImmediate(resolve));

export const runTests = () => {
  t.test("Checking performance", async (t) => {
    await waitForTick();
    for (let j = 0; j < 5_000; j++) {
      const a = j;
      t.test(`Checking for ${j}`, async (t) => {
        t.equal(a * 2, a + a);
      });
    }
  });
};

and a set of perf1.spec.ts - perf5.spec.ts with identical content:

import { runTests } from "./perf";

runTests();

When reporter=silent is used, tests finish in 6 seconds:

> yarn spec --reporter=silent
yarn run v1.22.19
$ tap run --disable-coverage "src/**/*.spec.ts" --reporter=silent
Done in 5.99s.

However, when standard reporter is used, runtime increases 2.5x, while CPU load stays high (more specifically, several CPU cores are used for several seconds, and then tap process consumes a single CPU core for several more seconds):

> yarn spec
yarn run v1.22.19
$ tap run --disable-coverage "src/**/*.spec.ts"
 PASS  src/perf5.spec.ts 5000 OK 7.531s
 PASS  src/perf4.spec.ts 5000 OK 7.593s
 PASS  src/perf3.spec.ts 5000 OK 7.643s
 PASS  src/perf1.spec.ts 5000 OK 7.704s
 PASS  src/perf2.spec.ts 5000 OK 9.196s


  🌈 TEST COMPLETE 🌈


Asserts:  25000 pass  0 fail  25000 of 25000 complete
Suites:       5 pass  0 fail          5 of 5 complete

# No coverage generated
# { total: 25000, pass: 25000 }
# time=13484.626ms

Done in 14.02s.

This only seems to happen when there are several test files.

My guess is that for every assert (out of 25k), node-tap has to update several lines on the screen, which takes more time than such a simple test. From the CPU load, it also seems that node-tap performs these 25k updates long after all tests have finished.

Maybe it would be better if node-tap throttled the screen update, to, say, no more than one update every 100ms. This is still fast enough to provide good UX, but not too fast to hit this bottleneck (as it will only need to update 60 times instead of 25k).

Or if it only displayed the last information (currently it looks as if it had a queue of screen states, and painted these states in order; that after 25k assertions have passed, it ends with 25k paint tasks in that queue... so not only it spends too much time painting these updates, but the updates themselves are most of the time very outdated).

Environment

> which tap
> yarn list tap
yarn list v1.22.19                                                                                                   
warning Filtering by arguments is deprecated. Please use the pattern option instead.                                 
└─ tap@18.7.2
Done in 0.72s.                                                                                                       
> yarn run tap versions
yarn run v1.22.19                                                                                                    
$ [PROJECT_DIRECTORY]/node_modules/.bin/tap versions                                       
tap: 18.7.2
"@tapjs/config": 2.4.17
"@tapjs/core": 1.5.2
"@tapjs/run": 1.5.2
"@tapjs/stack": 1.2.8
"@tapjs/test": 1.4.2
tap-parser: 15.3.2
tap-yaml: 2.2.2
tcompare: 6.4.6
plugins:
  "@tapjs/after": 1.1.20
  "@tapjs/after-each": 1.1.20
  "@tapjs/asserts": 1.1.20
  "@tapjs/before": 1.1.20
  "@tapjs/before-each": 1.1.20
  "@tapjs/filter": 1.2.20
  "@tapjs/fixture": 1.2.20
  "@tapjs/intercept": 1.2.20
  "@tapjs/mock": 1.3.2
  "@tapjs/node-serialize": 1.3.2
  "@tapjs/snapshot": 1.2.20
  "@tapjs/spawn": 1.1.20
  "@tapjs/stdin": 1.1.20
  "@tapjs/typescript": 1.4.2
  "@tapjs/worker": 1.1.20
Done in 0.31s.                                                                                                       
> yarn tap config list
yarn run v1.22.19                                                                                                    
$ [PROJECT_DIRECTORY]/node_modules/.bin/tap config list                                    
# vim: set filetype=yaml :
color: false
coverage-report:
  - text
exclude:
  - "**/@(fixture*(s)|dist)/**"
include:
  - "**/@(test?(s)|__test?(s)__)/**/*.@(js|cjs|mjs|tap|cts|jsx|mts|ts|tsx)"
  - "**/*.@(test?(s)|spec).@(js|cjs|mjs|tap|cts|jsx|mts|ts|tsx)"
  - "**/test?(s).@(js|cjs|mjs|tap|cts|jsx|mts|ts|tsx)"
jobs: 12
reporter: tap
snapshot-clean-cwd: true
timeout: 30
Done in 0.32s.                                                                                                       
> yarn tap plugin list
yarn run v1.22.19                                                                                                    
$ [PROJECT_DIRECTORY]/node_modules/.bin/tap plugin list                                    
node:internal/process/esm_loader:97
    internalBinding('errors').triggerUncaughtException(
                              ^

[Error: Cannot find package '@tapjs/core' imported from [PROJECT_DIRECTORY]/x] {
  code: 'ERR_MODULE_NOT_FOUND'
}
error Command failed with exit code 1.                                                                               
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.                                 
> yarn list @isaacs/ts-node-temp-fork-for-pr-2009
yarn list v1.22.19                                                                                                   
warning Filtering by arguments is deprecated. Please use the pattern option instead.                                 
└─ tap@18.7.2
   └─ @isaacs/ts-node-temp-fork-for-pr-2009@10.9.5
Done in 0.70s.                                                                                                       
> yarn list typescript
yarn list v1.22.19                                                                                                   
warning Filtering by arguments is deprecated. Please use the pattern option instead.                                 
├─ tap@18.7.2
│  ├─ tshy@1.14.0
│  │  └─ typescript@5.4.5
│  └─ typescript@5.2.2
└─ typescript@5.4.2
Done in 0.76s.                                                                                                       
> uname -a
Linux [MACHINE_NAME] 6.6.24-0-lts #1-Alpine SMP PREEMPT_DYNAMIC Thu, 04 Apr 2024 12:08:14 +0000 x86_64 Linux