performance degredation

[collintime]

Hey, I just wanted to say congrats on the latest release. I've been using tap a long time! Our project has struggled with closing the process completely for a long time, and this latest release has helped me track down issues more successfully with the debug flag. It would be awesome if any SIGTERM/KILLS/WHATEVER could report on all open handles. If that is possible, let me know and I'll open a ticket!

On to the point: I'm dealing with a large, old set of tests: 206 suites, 8790 asserts. They include integration style tests with a running server, postgres, etc. Tap 16 could complete this suite in 11m.

The latest Tap release has changed that. On both node 16 and 18 it's taking much longer, completing in ~1h locally. This is consistent across multiple dev machines. Slower machines (CI/CD runners) can no longer complete the tests, timing out at ~6h.

For fun I've tried the following test file, running with tap as well as node directly. Unfortunately, reproducibility suffers across users here, but version 18 seems slower across the board. Additionally, the time discrepancy between tap and node appears to have widened.

import Tap from 'tap'
Tap.test('whatever', async test => {
    test.ok(true, 'it should be ok')
    test.end()
})

For some of our users, running via tap takes seconds now, while running via node finishes in the low hundreds of milliseconds. For others the difference isn't as noticeable. Granted, this feels like a bad benchmark.

One more thing I noticed: If i put that file into the aforementioned large project directory and run tap ./test.js it takes almost 10s to complete. For large portions of this time, a timer ticks without any output. In a new project directory the test runs as expected on version 16 and slower on version 18.

Please let me know if i can provide any additional details. I hope I haven't missed something obvious in the config.

Thank you!

[isaacs]

Are you using typescript? If not, try tap plugin rm @tapjs/typescript.

If so, or maybe along with it, try tap config set typecheck=false.

In my experience so far, the huge perf hit is usually ts-node doing type checking, the fact that it's so much slower in a big project dir really makes that seem more likely.

If that fixes the problem for you, I'll probably make typecheck default to false on the next release.

[isaacs]

If it is a ts-node issue, then it can also be affected pretty profoundly by your tsconfig.json compilerOptions. What do you have in there? If it's triggering some large strict tree-walking type checks, that can be pretty extreme.

[collintime]

Great suggestions! We do use typescript, but our project is compiled and we run tests from ts-out

tsconfig:

{
  "compilerOptions": {
    "target": "ESNext",
    "module": "NodeNext",
    "moduleResolution": "nodenext",
    "resolveJsonModule": true,
    "allowJs": true,
    "sourceMap": true,
    "outDir": "./ts-out",
    "esModuleInterop": true,
    "forceConsistentCasingInFileNames": true,
    "strict": true,
    "noImplicitAny": false,
    "strictBindCallApply": false,
    "skipLibCheck": true
  },
  "include": ["./src/**/*"],
  "ts-node": {
    "files": true,
    "moduleTypes": {
      "**/tap-snapshots/**/*": "cjs"
    }
  }
}

Narrowing down one slow test with the config you described is interesting.

package.json:

"test-one": "tap ts-out/the-test.spec.js"
...
  "tap": {
    "typecheck": false,
    "jobs": 1,
    "timeout": 0,
    "debug": true,
    "plugin": [
      "!@tapjs/typescript"
    ]
  }

npm run compile && npm run test-one

...
TAP 30020 TAP:       TAP_DEBUG: '1',
TAP 30020 TAP:       TAP_SNAPSHOT_CLEAN_CWD: '1',
TAP 30020 TAP:       TAP_TYPECHECK: '0',
...
TAP 30020 TAP:     args: [
TAP 30020 TAP:       '--loader=ts-node/esm',
TAP 30020 TAP:       '--loader=@tapjs/mock/loader',
TAP 30020 TAP:       '--no-warnings=ExperimentalLoader',
TAP 30020 TAP:       '--enable-source-maps',
TAP 30020 TAP:       '--loader=@tapjs/processinfo/loader',
TAP 30020 TAP:       '<path>/the-test.spec.js'
TAP 30020 TAP:     ],

Its difficult to get a feel for timing and order of operations, but it feels like a surprise compile-like step is taking place prior to any testing.

[isaacs]

Ah, there's this:

"allowJs": true,

Even though you're running the tests as JavaScript, they're being run with the ts-node/esm loader, and since "allowJs" is enabled, it's running the JavaScript through the (much slower!) allowJs JavaScript typechecking.

If you take that out (or add "ts-node": { "compilerOptions": { "allowJs": false }}), then do things speed up to acceptable levels?

I'm a little bit surprised that it's running with --loader=ts-node/esm when the @tapjs/typescript plugin is disabled. It will indeed perform a tap build if the plugins in the config don't match the plugins that are built into the tap Test class, but that should only happen the first time, before running any tests, and from then on, it should match (since it's already been built at that point).

Any chance this is a repo that you could link to or give me access to? I'd love to see it happen if possible.

[isaacs]

It could be that the build-on-demand isn't removing @tapjs/typescript because the "typecheck": false config is unrecognized if @tapjs/typescript isn't enabled? Maybe try removing that config, and run tap build, and see if that speeds things up?

I'm as sure as I can be that it's typescript-related somehow. The use of proxies and loaders does add some overhead above what node 16 did, but it should definitely not be more than 5-10% slower on average.

[isaacs]

Ok, here's what I'm seeing: there are essentially a few different sources of slowness happening here:

• The @tapjs/mock and @tapjs/typescript plugins both use loaders. These are just fundamentally a bit slower, because node has to call additional functions and set stuff up, and I suspect it's just not as optimized as it could be. For the test.js that you pasted above, I'm seeing that add about 50ms for @tapjs/mock, and around 100ms for @tapjs/typescript on my system, with typecheck: false and allowJs removed from tsconfig.json.
• Putting typecheck: true in the config doesn't have much of an effect, because it's JavaScript, so ts won't typecheck it by default anyway.
• Putting allowJs: true in the tsconfig doubles the time, seems to be even slightly more so than the effect of running a .ts test with typecheck: true (though it's within the range of noise, and I haven't tested this particularly rigorously).
• The coverage and process checking (ie, the loader coming from @tapjs/processinfo) has gotten a bit slower. It's not a huge effect, but more than I'd like. The last few batches of changes to processinfo have been correctness fixes and node v20 support, but I need to spend a bit of effort making sure it's as optimized as it can be.

[isaacs]

Just shipped 18.1, which makes typecheck false by default. That should improve things considerably.

Next task will be digging into processinfo for perf improvements.

[collintime]

allowJs: false brings the entire suite within ~1m of v16! However, we currently need to allow javascript files when we build, and we prefer to test the build output destined for deployment.

This solution is surprising, especially with the removal of the typescript plugin, and I'd have never guessed that I shouldn't "allow js files in my double secret compile from js to js" 😄

Tap v18 assumes I'll need to compile my tests, and the presence of flags like typecheck, plugins, etc lead me to believe I'll have more control than I do. Can I bypass compile with one flag? Also, It might be slick if the output indicated time spent, or steps taken, in a more granular way.

Thanks for looking into this!

[isaacs]

So, in the immediate term, to keep your builds the same but make tests fast, you can create a file at tsconfig.test.json containing:

{
  "extends": "./tsconfig.json",
  "compilerOptions": {
    "allowJs": false
  }
}

And add this to package.json:

{
  "tap": {
    "tsconfig": "./tsconfig.test.json"
  }
}

I'll have a think on a better way to make this a bit smoother. In general, you almost never want allowJs when using ts-node (at best, it screws up sourcemaps in a weird way, at worst, it's punishingly slow), and usually want it when using tsc directly, for type safety, so it's kind of a footgun.

Better perf tracking in the debug output is definitely on my radar, just haven't gotten to it yet.

[piotr-cz]

I found out that you have to explicitly disable typecheck, even that v18.1 changelog says it's disabled by default

[isaacs]

I found out that you have to explicitly disable typecheck, even that v18.1 changelog says it's disabled by default

🤦 Yes, you are correct. I'd been disabling it in a bunch of my modules explicitly, so didn't notice. There were even tests verifying that it still is unset by default lol. Will be fixed in 18.3.1 patch release.

[isaacs]

Update: this will be addressed more satisfactorily by the introduction of a new typescript importer that can do type checking and uses a persistent daemon process to avoid repeatedly creating the same Program object (which is the part that takes from 400ms anywhere up to multiple seconds, and is done for every test file).

I have the general approach sketched out and validated at this point, but it's still not quite ready for prime time.

[Laurensdc]

For us, running the tests with --debug goes smoothly (takes about 2s) all the way to and including the following output:

TAP 394 TAP: done processing [] null false
TAP 394 TAP: idle after #process false null
TAP 394 TAP: OIE(TAP) shifted into queue []
TAP 394 TAP: PROCESSING(TAP) 0
TAP 394 TAP: > end of queue
TAP 394 TAP: done processing [] null false
TAP 394 TAP: idle after #process false null
TAP 394 Purchases in a new week add points again: > EOF Purchases in a new week add points again
TAP 394 Purchases in a new week add points again: eof end parser Purchases in a new week add points
again
TAP 394 Purchases in a new week add points again: > end of queue
TAP 394 Purchases in a new week add points again: done processing [] null Symbol(implicit end)
TAP 394 Purchases in a new week add points again: idle after #process Symbol(implicit end) null
TAP 394 Purchases in a new week add points again: awaited end in process Symbol(implicit end)
TAP 394 Purchases in a new week add points again: END Purchases in a new week add points again
implicit=true
TAP 394 Purchases in a new week add points again: already ended, ignore implicit end

After that, it takes tap another 10 seconds to do seemingly nothing, all tests have run, and then we get the following debug output:

TAP 394 TAP: END TAP implicit=true
TAP 394 TAP: push obe
TAP 394 TAP: END(TAP) implicit plan 13
TAP 394 TAP: END TAP implicit=true
TAP 394 TAP: #end: queue not empty, or occupied false null [ '1..13\n' ]
TAP 394 TAP: PROCESSING(TAP) 1
TAP 394 TAP: > STRING
TAP 394 TAP: LINE "1..13\n" [ 'TAP', '' ]
TAP 394 TAP: > end of queue
TAP 394 TAP: done processing [] null Symbol(implicit end)
TAP 394 TAP: idle after #process Symbol(implicit end) null
TAP 394 TAP: awaited end in process Symbol(implicit end)
TAP 394 TAP: END TAP implicit=true
TAP 394 TAP: set ended=true
TAP 394 TAP: PROCESSING(TAP) 1
TAP 394 TAP: > EOF TAP
TAP 394 TAP: call onEOF TAP
TAP 394 TAP: onEOF is promise
TAP 394 TAP: < already processing
TAP 394 TAP: done processing [
TAP 394 TAP:   Waiter {
TAP 394 TAP:     cb: [Function (anonymous)],
TAP 394 TAP:     ready: false,
TAP 394 TAP:     value: undefined,
TAP 394 TAP:     resolved: false,
TAP 394 TAP:     rejected: false,
TAP 394 TAP:     done: false,
TAP 394 TAP:     finishing: false,
TAP 394 TAP:     expectReject: false,
TAP 394 TAP:     promise: Promise {
TAP 394 TAP:       <pending>,
TAP 394 TAP:       [Symbol(async_id_symbol)]: 4318,
TAP 394 TAP:       [Symbol(trigger_async_id_symbol)]: 0
TAP 394 TAP:     },
TAP 394 TAP:     resolve: [Function (anonymous)]
TAP 394 TAP:   }
TAP 394 TAP: ] null Symbol(implicit end)
TAP 339 test/routes/earned-steps.ts: LINE "1..13\n" [ 'test/routes/earned-steps.ts', '    ' ]
TAP 339 TAP: LINE "    1..13\n" [ 'TAP', '' ]

2> test/routes/earned-steps.ts
TAP 394 TAP: PROCESSING(TAP) 1
TAP 394 TAP: done processing [] Waiter {
TAP 394 TAP:   cb: [Function (anonymous)],
TAP 394 TAP:   ready: true,
TAP 394 TAP:   value: undefined,
TAP 394 TAP:   resolved: false,
TAP 394 TAP:   rejected: false,
TAP 394 TAP:   done: false,
TAP 394 TAP:   finishing: false,
TAP 394 TAP:   expectReject: false,
TAP 394 TAP:   promise: Promise {
TAP 394 TAP:     <pending>,
TAP 394 TAP:     [Symbol(async_id_symbol)]: 4318,
TAP 394 TAP:     [Symbol(trigger_async_id_symbol)]: 0
TAP 394 TAP:   },
TAP 394 TAP:   resolve: [Function (anonymous)]
TAP 394 TAP: } Symbol(implicit end)
TAP 394 TAP: set ended=true
TAP 394 TAP: PROCESSING(TAP) 1
TAP 394 TAP: done processing [ Symbol(EOF) ] Waiter {
TAP 394 TAP:   cb: [Function (anonymous)],
TAP 394 TAP:   ready: true,
TAP 394 TAP:   value: undefined,
TAP 394 TAP:   resolved: false,
TAP 394 TAP:   rejected: false,
TAP 394 TAP:   done: false,
TAP 394 TAP:   finishing: false,
TAP 394 TAP:   expectReject: false,
TAP 394 TAP:   promise: Promise {
TAP 394 TAP:     <pending>,
TAP 394 TAP:     [Symbol(async_id_symbol)]: 4318,
TAP 394 TAP:     [Symbol(trigger_async_id_symbol)]: 0
TAP 394 TAP:   },
TAP 394 TAP:   resolve: [Function (anonymous)]
TAP 394 TAP: } Symbol(implicit end)
TAP 394 TAP: PROCESSING(TAP) 2
TAP 394 TAP: done processing [ Symbol(EOF), Symbol(EOF) ] Waiter {
TAP 394 TAP:   cb: [Function (anonymous)],
TAP 394 TAP:   ready: true,
TAP 394 TAP:   value: undefined,
TAP 394 TAP:   resolved: true,
TAP 394 TAP:   rejected: false,
TAP 394 TAP:   done: true,
TAP 394 TAP:   finishing: true,
TAP 394 TAP:   expectReject: false,
TAP 394 TAP:   promise: Promise {
TAP 394 TAP:     <pending>,
TAP 394 TAP:     [Symbol(async_id_symbol)]: 4318,
TAP 394 TAP:     [Symbol(trigger_async_id_symbol)]: 0
TAP 394 TAP:   },
TAP 394 TAP:   resolve: [Function (anonymous)]
TAP 394 TAP: } Symbol(implicit end)
TAP 394 TAP: PROCESSING(TAP) 2
TAP 394 TAP: > EOF TAP
TAP 394 TAP: eof end parser TAP
TAP 394 TAP: ONCOMPLETE "TAP"
{"ok":true,"count":13,"pass":13,"fail":0,"bailout":false,"todo":0,"skip":0,"failures":[],"time":null,
"plan":{"start":1,"end":13,"skipAll":false,"skipReason":"","comment":""},"skips":[],"todos":[]}
TAP 394 TAP: > EOF TAP
TAP 394 TAP: eof end parser TAP
TAP 394 TAP: > end of queue
TAP 394 TAP: done processing [] null Symbol(implicit end)
TAP 394 TAP: idle after #process Symbol(implicit end) null
TAP 394 TAP: awaited end in process Symbol(implicit end)
TAP 394 TAP: END TAP implicit=true
TAP 394 TAP: already ended, ignore implicit end
TAP 339 test/routes/earned-steps.ts: ONCOMPLETE "test/routes/earned-steps.ts"
{"ok":true,"count":13,"pass":13,"fail":0,"bailout":false,"todo":0,"skip":0,"failures":[],"time":null,
"plan":{"start":1,"end":13,"skipAll":false,"skipReason":"","comment":""},"skips":[],"todos":[]}

 PASS  test/routes/earned-steps.ts 44 OK 12s

TAP 339 test/routes/earned-steps.ts: SPAWN close 0 null
TAP 339 TAP: onIndentedEnd test/routes/earned-steps.ts
TAP 339 TAP: #onIndentedEnd TAP(test/routes/earned-steps.ts)
TAP 339 TAP: OIE(TAP) >shift into queue []
TAP 339 TAP: LINE "ok 1 - test/routes/earned-steps.ts # time=12212.635ms\n" [ 'TAP', '' ]
TAP 339 TAP: LINE "\n" [ 'TAP', '' ]
TAP 339 TAP: PROCESSING(TAP) 0
TAP 339 TAP: > end of queue
TAP 339 TAP: done processing [] null false
TAP 339 TAP: idle after #process false null
TAP 339 TAP: END TAP implicit=true
TAP 339 TAP: push obe
TAP 339 TAP: set ended=true
TAP 339 TAP: PROCESSING(TAP) 1
TAP 339 TAP: > EOF TAP
TAP 339 TAP: call onEOF TAP
TAP 339 TAP: onEOF is promise
TAP 339 TAP: < already processing
TAP 339 TAP: done processing [
TAP 339 TAP:   Waiter {
TAP 339 TAP:     cb: [Function (anonymous)],
TAP 339 TAP:     ready: false,
TAP 339 TAP:     value: undefined,
TAP 339 TAP:     resolved: false,
TAP 339 TAP:     rejected: false,
TAP 339 TAP:     done: false,
TAP 339 TAP:     finishing: false,
TAP 339 TAP:     expectReject: false,
TAP 339 TAP:     promise: Promise {
TAP 339 TAP:       <pending>,
TAP 339 TAP:       [Symbol(async_id_symbol)]: 2593,
TAP 339 TAP:       [Symbol(trigger_async_id_symbol)]: 2138
TAP 339 TAP:     },
TAP 339 TAP:     resolve: [Function (anonymous)]
TAP 339 TAP:   }
TAP 339 TAP: ] null false
TAP 339 TAP: PROCESSING(TAP) 1
TAP 339 TAP: done processing [] Waiter {
TAP 339 TAP:   cb: [Function (anonymous)],
TAP 339 TAP:   ready: true,
TAP 339 TAP:   value: undefined,
TAP 339 TAP:   resolved: false,
TAP 339 TAP:   rejected: false,
TAP 339 TAP:   done: false,
TAP 339 TAP:   finishing: false,
TAP 339 TAP:   expectReject: false,
TAP 339 TAP:   promise: Promise {
TAP 339 TAP:     <pending>,
TAP 339 TAP:     [Symbol(async_id_symbol)]: 2593,
TAP 339 TAP:     [Symbol(trigger_async_id_symbol)]: 2138
TAP 339 TAP:   },
TAP 339 TAP:   resolve: [Function (anonymous)]
TAP 339 TAP: } false
TAP 339 TAP: PROCESSING(TAP) 0
TAP 339 TAP: done processing [] Waiter {
TAP 339 TAP:   cb: [Function (anonymous)],
TAP 339 TAP:   ready: true,
TAP 339 TAP:   value: undefined,
TAP 339 TAP:   resolved: false,
TAP 339 TAP:   rejected: false,
TAP 339 TAP:   done: false,
TAP 339 TAP:   finishing: false,
TAP 339 TAP:   expectReject: false,
TAP 339 TAP:   promise: Promise {
TAP 339 TAP:     <pending>,
TAP 339 TAP:     [Symbol(async_id_symbol)]: 2593,
TAP 339 TAP:     [Symbol(trigger_async_id_symbol)]: 2138
TAP 339 TAP:   },
TAP 339 TAP:   resolve: [Function (anonymous)]
TAP 339 TAP: } false
TAP 339 TAP: OIE(TAP) shifted into queue []
TAP 339 TAP: PROCESSING(TAP) 0
TAP 339 TAP: done processing [] Waiter {
TAP 339 TAP:   cb: [Function (anonymous)],
TAP 339 TAP:   ready: true,
TAP 339 TAP:   value: undefined,
TAP 339 TAP:   resolved: false,
TAP 339 TAP:   rejected: false,
TAP 339 TAP:   done: false,
TAP 339 TAP:   finishing: false,
TAP 339 TAP:   expectReject: false,
TAP 339 TAP:   promise: Promise {
TAP 339 TAP:     <pending>,
TAP 339 TAP:     [Symbol(async_id_symbol)]: 2593,
TAP 339 TAP:     [Symbol(trigger_async_id_symbol)]: 2138
TAP 339 TAP:   },
TAP 339 TAP:   resolve: [Function (anonymous)]
TAP 339 TAP: } false

We are on the latest version of tap (so typecheck is disabled by default) and we don't have the allowJS option enabled.