Extreme boot time difference when concurrency specified

[ackerdev]

Description

There appears to be a significant "boot time" (presumably transpiling and spawning child processes?) difference for ava when specifying concurrency, even with ridiculously high numbers.

With my suite of 103 tests across 36 files, running ava without specifying any concurrency, the spinning indicator would be the only output for upwards of 30 seconds, after which the test output would speed by and the suite would complete with total time nearing a minute.

After seeing #966 I experimented with the concurrency option, and noticed a drastic difference in execution speed, even when the number provided was a radically high number (higher than my system's logical cores, higher than the number of test files...).

$ time ava

  103 passed

ava  53.32s user 4.79s system 107% cpu 53.955 total

$ time ava -c 1000

  103 passed

ava -c 1000  82.23s user 6.56s system 671% cpu 13.225 total

Perhaps there is an unexpected performance difference in how Bluebird.map works when concurrency is left to default to 0?

Config

"ava": {
  "files": [
    "test"
  ],
  "source": [
    "src"
  ]
}

Environment

Node.js v6.9.4
darwin 16.4.0
ava 0.18.2
npm 3.10.10

[novemberborn]

I'm surprised by the difference in CPU usage. Something seems to be doing significantly more work, though I doubt it's Bluebird#map(). Does it do the same if you set concurrency to 36?

I assume you can't share your test suite?

[ackerdev]

Results appear to be very similar as long as concurrency is >= the number of logical cores on the machine. And unfortunately no I cannot share the test suite; if it helps any, they're all unit tests running as test.serial, and it's a suite for an HTTP API server. No tests go through the web framework, and there are a few connections to external resources like SQL, Redis, that may be leaking in the tests currently, though they are not testing interactions with those resources directly yet.

$ time ava -c 8

  110 passed

ava -c 8  85.90s user 7.11s system 644% cpu 14.432 total

$ time ava -c 36

  110 passed

ava -c 36  91.18s user 7.27s system 628% cpu 15.658 total

My thought regarding Bluebird wasn't so much that Bluebird#map was broken or directly responsible, but rather perhaps when concurrency limiting is enabled, event-loop scheduling might be different such that spawning child processes doesn't result in a lockup. Just a guess though, didn't really dig very far down into the depths.

[jamestalmage]

If I had to guess, it would be how we handle test.only when no concurrency is specified. We wait for all test files to load and specify all their tests and transmit the ready event.

If we can prove that to be true, I propose we abandon the current .only behavior, and have it behave similar to how it works when --concurrency is specified.

We can almost certainly catch 99% of t.only uses via static analysis with a babel plugin. I started on this a year ago, but my life got hectic and I never followed through, see: ava-test-data.

[novemberborn]

@jamestalmage the surprising behavior in this issue is that specifying concurrency slows the tests down more than not specifying it does.

[jamestalmage]

Right. When you specify concurrency, we run tests as soon as possible. When you don't, we pause, waiting for all tests to load and report back about t.only