Slow per-file startup

[ronen]

[Sorry pressed the submit button prematurely by mistake]

I'm running all my tests serially, with only one process at a time, i.e.:

{
  concurrency: 1,
  serial: true,
  verbose: true,
}

(Because most all tests need access to a local server that doesn't support concurrent requests... #2048 would fix that!)

And I see a several-second delay before each file's tests start running.

I'm compiling my sources as per https://github.com/avajs/ava/blob/master/docs/recipes/babel.md#compile-sources so that is likely contributing/causing. But I'd expect the cacheing mechanism to minimize the need to recompile?

Is there any way I can trace what's going on to prepare each file so I can see where the time is being spent and what if any optimizations I could look into?

Thanks!

Environment

Tell us which operating system you are using, as well as which versions of Node.js, npm, and AVA. Run the following to get it quickly:

node -e "var os=require('os');console.log('Node.js ' + process.version + '\n' + os.platform() + ' ' + os.release())"
npx ava --version
npm --version

Node.js v12.10.0
darwin 18.7.0
2.4.0
6.11.3

[novemberborn]

IIRC there's no way to see the timings of the steps taken to start running tests from a particular file. I guess we could instrument fork.js with debug for that.

[ronen]

IIRC there's no way to see the timings of the steps taken to start running tests from a particular file. I guess we could instrument fork.js with debug for that.

OK, I guess you can put that down as a (minor) feature request :)

Also in the mix, I forgot to mention, If I use nyc that adds to the slowdown. Not sure whether/how instrumenting fork.js would help in figuring out nyc's contribution...

[novemberborn]

It would probably include the delay added by nyc but it won't make it easy to attribute a specific percentage to nyc.

[shusson]

We've also noticed a significant delay between test files in ava 3.8.2. We have 150 test files and 1300 tests and we notice that ~10min is spent running test files and ~6min is spent in overhead. I measured "time spent running a test" by profiling https://github.com/avajs/ava/blob/master/lib/runner.js#L378 and "overhead" by subtracting time spent from total time for the whole suite measured by my system.

Our tests could be the cause of this delay(I'm guessing something could prevent the test process from terminating?), but it would be nice to get a warning from ava if there is a significant delay between tests.

[novemberborn]

@shusson that doesn't sound too great! It would really help if we could pin down where the time is being spent. For instance, instrumenting that start() function excludes the time it takes to load any code in the test file.

You're not using things like @babel/register or ts-node by any chance, right?

[shusson]

It would really help if we could pin down where the time is being spent

Yeah we are still investigating, I will post an update when we have one.

You're not using things like @babel/register or ts-node by any chance, right?

No, we transpile all our typescript and run ava against the js.

[novemberborn]

I will post an update when we have one.

Thanks. There can be many variables at play here. I have a test suite with 34 files / 500 tests which runs really smoothly…

[shusson]

@novemberborn Our delay happens when ava requires each test file here: https://github.com/avajs/ava/blob/master/lib/worker/subprocess.js#L190. I guess this is the price we pay for test file isolation and having a ~400 dependencies :(

It might be useful for others to have ava log a warning if the require takes longer than 1 second.

[novemberborn]

Right so it's the bootstrap time of your (test) dependencies, plus then declaring the tests. I agree it may be useful to report that… maybe if the time spend just loading the test file is over a certain percentage of total run time?

If only so that, uhm — and I know you weren't doing this — AVA isn't blamed 😉

This I think is the one use case for letting you run all test files in a single process / thread, so that you can better utilize caches. As long as tests don't have side-effects in the process itself.

[shusson]

If only so that, uhm — and I know you weren't doing this — AVA isn't blamed

:D I would rephrase it to: "AVA helping you discover that your app takes forever to load dependencies"

As long as tests don't have side-effects in the process itself.

yes one of the reasons we migrated to AVA was jestjs/jest#8331

[powersjcb]

It looks like there used to be debug tooling to enable this that was removed in 2018.

f803a22