Unexpected speed increase in `deno test` in 1.30.1

[GJZwiers]

The tests in several of my projects are running a great deal faster since commit https://github.com/denoland/deno/commit/e85ca8be0dafdab28e6283aed64c8ee0eb3a338d. The changes have been reverted in https://github.com/denoland/deno/commit/3f8c217bb1a1b5cf2ceafa0396f6492417acfb22 but I was asked on Discord to make a reproduction for further investigation.

The effect can be seen when running the following example tests:

import { assertEquals } from "https://deno.land/[email protected]/testing/asserts.ts";

function handleInput(
  answer: string,
): boolean {
  return (answer === "yes") ? true : false;
}

Deno.test("debug test", () => {
  const answer = handleInput("yes");
  assertEquals(answer, true);
});

Deno.test("debug test 2", () => {
  const answer = handleInput("no");
  assertEquals(answer, false);
});

Deno.test("debug test 3", () => {
  const answer = handleInput("ok");
  assertEquals(answer, false);
});

In Deno 1.30.0:

deno test debug.test.ts
running 3 tests from ./debug.test.ts
debug test 2 ... ok (36ms)
debug test ... ok (32ms)
debug test 3 ... ok (32ms)

ok | 3 passed | 0 failed (129ms)

In 1.30.1:

deno test debug.test.ts
running 3 tests from ./debug.test.ts
debug test ... ok (7ms)
debug test 2 ... ok (3ms)
debug test 3 ... ok (3ms)

ok | 3 passed | 0 failed (54ms)

[aapoalas]

I am able to replicate a small difference on my ArchLinux machine: 1.30.1 performs the tests in 28 milliseconds or more, 1.30.2 on 30 millsieconds or more. 1.30.0 seemed to be in line with the 30 milliseconds.

I cannot replicate this large difference.

[GJZwiers]

I ran the tests on windows, but I just tried it on macOS and there appears to be no noticeable difference on there between running 1.30.0 and 1.30.1. So it could be a windows issue that was somehow fixed by https://github.com/denoland/deno/commit/e85ca8be0dafdab28e6283aed64c8ee0eb3a338d. Maybe related to https://github.com/denoland/deno/issues/14621?

[littledivy]

Cannot reproduce on macOS either.

[littledivy]

It seems https://github.com/denoland/deno/commit/e85ca8be0dafdab28e6283aed64c8ee0eb3a338d caused ~47+ wakeups before a test completes, this means the CPU usage spiked to 100% and it was continously waking up the Rust future that gets the test results.

https://github.com/denoland/deno/blob/0eb5be9a1204f959d3daac8cd7b1b342320970fd/cli/tools/test.rs#L1057-L1065

Before https://github.com/denoland/deno/commit/e85ca8be0dafdab28e6283aed64c8ee0eb3a338d, the wakeup calls were 1 (correct and expected) before a test completes.

So its likely that the speed up is because the test collector is forced into a busy loop to get results as quickly as possible.

Now, why is it only noticable on Windows? I did some profiling, notice GetQueuedCompletionStatusEx. So many NTReadFile calls also seem weird.

Deno 1.30.1:

(30-40ms per test)

Deno 1.30.0:

(3-5ms per test)

I used Very Sleepy CPU profiler and ran the test cases 10000 times. (edit: s/1000/10000)

[bartlomieju]

@GJZwiers is this issue still relevant?

[GJZwiers]

I haven't checked this on Windows for a while, so I'm not sure (I can look into it next week but I'm out of town for a few days). I think this could be closed because while the test runs were somewhat slower on Windows it doesn't seem to be a blocker for anthing in particular.

[bartlomieju]

Alright, closing for now then.