Isolates scaling problem

[jensjoha]

On the CFE team we have quite a bit of "suites", to speed things up (and integrate with the approval system and whatnot) we have a "unit test suites" runner which launches the suites in isolates (using #cores-1 isolates).

My machine has 12 cores (with hyperthreading) and so it launches 11 isolates. According to htop though it only uses 4-500% CPU though. Prepending a run with time gives this:

(Runs on f774ec5)

$ time out/ReleaseX64/dart pkg/front_end/test/unit_test_suites.dart --skipTestsThatRequireGit
[...]
real    10m34.861s
user    41m52.658s
sys     10m22.388s

Using (user+sys)/real this becomes ~494% CPU.

If instead launching two processes, asking each to do half and only use 5 isolates each:

time out/ReleaseX64/dart pkg/front_end/test/unit_test_suites.dart --skipTestsThatRequireGit -j5 --shards 2 --shard 1
time out/ReleaseX64/dart pkg/front_end/test/unit_test_suites.dart --skipTestsThatRequireGit -j5 --shards 2 --shard 2

(run in two different terminals at the same time)

I get these numbers:

[...]
real    5m31.369s
user    18m8.244s
sys     2m56.053s

Using (user+sys)/real this becomes ~381% CPU.

and

[...]
real    5m39.273s
user    18m16.937s
sys     2m54.928s

Using (user+sys)/real this becomes ~374% CPU.

Adding up these numbers it becomes ~755% CPU (or ~747% if doing (user1+sys1+user2+sys2)/max(real1, real2)) --- in both cases quite a bit more than the <500% (more than 50% more actually).
Looking at the (real) runtime it's almost twice as fast (~87% faster, taking ~53.5% of the time).

So: Are isolates expected to be slower, is it being held wrong or is something else up?

@mraleph suggested that "the answer is probably our GC does not scale well for this usecase" and suggested I file a bug, so here we are.

[rmacnak-google]

While the GC could do better here, I think this is mostly from uneven work distribution across the isolates. I noticed the timeline often had fewer open HandleMessage events than the number of workers, especially toward the end. Here I've grouped the events by isolate instead of thread. (-j12, also --shards 4 --shard 1 because otherwise the trace is too big for Catapult to handle).

--- a/pkg/front_end/test/unit_test_suites.dart
+++ b/pkg/front_end/test/unit_test_suites.dart
@@ -6,6 +6,7 @@ import 'dart:async' show Timer;
 import 'dart:convert' show jsonEncode;
 import 'dart:io' show File, Platform, exitCode;
 import 'dart:isolate' show Isolate, ReceivePort, SendPort;
+import 'dart:developer';
 
 import 'package:args/args.dart' show ArgParser;
 import 'package:testing/src/chain.dart' show CreateContext, Result, Step;
@@ -502,9 +503,11 @@ class SuiteConfiguration {
 }
 
 Future<void> runSuite(SuiteConfiguration configuration) async {
+  var t = new TimelineTask();
   Suite suite = configuration.suite;
   String name = suite.prefix;
   String fullSuiteName = "$suiteNamePrefix/$name";
+  t.start(fullSuiteName);
   Uri suiteUri = Platform.script.resolve(suite.path ?? "${name}_suite.dart");
   if (!new File.fromUri(suiteUri).existsSync()) {
     throw "File doesn't exist: $suiteUri";
@@ -528,6 +531,7 @@ Future<void> runSuite(SuiteConfiguration configuration) async {
     shards: suite.shardCount,
     shard: configuration.shard,
   );
+  t.finish();
   if (logger.gotFrameworkError) {
     throw "Got framework error!";
   }

[jensjoha]

Let's try something slightly different to make it more apples to apples:

import "dart:isolate";

import "unit_test_suites.dart" as suite;

void entry(List<String> args) {
  suite.main(args);
}

Future<void> main() async {
  ReceivePort exitPort1 = new ReceivePort();
  await Isolate.spawn(entry,
      ["--skipTestsThatRequireGit", "-j5", "--shards", "2", "--shard", "1"],
      onExit: exitPort1.sendPort);
  ReceivePort exitPort2 = new ReceivePort();
  await Isolate.spawn(entry,
      ["--skipTestsThatRequireGit", "-j5", "--shards", "2", "--shard", "2"],
      onExit: exitPort2.sendPort);
  await exitPort1.first;
  await exitPort2.first;
  print("done");
}

vs

time out/ReleaseX64/dart pkg/front_end/test/unit_test_suites.dart --skipTestsThatRequireGit -j5 --shards 2 --shard 1
time out/ReleaseX64/dart pkg/front_end/test/unit_test_suites.dart --skipTestsThatRequireGit -j5 --shards 2 --shard 2

(run in two different terminals at the same time)

This should do the exact same thing, with the exact same work distribution, just using either isolates or processes.

Using the isolates approach I get

[...]
Entire run took 0:07:25.244488.
[...]
Entire run took 0:07:25.573479.
done

real    7m38.368s
user    27m46.395s
sys     8m43.946s

So it finished in 7 minutes 38 seconds real runtime, using ~478% CPU.

Running in processes I get

[...]
Entire run took 0:03:50.552587.

real    4m4.012s
user    12m31.571s
sys     2m36.091s

and

[...]
Entire run took 0:04:09.658705.

real    4m23.415s
user    13m25.618s
sys     2m41.306s

So it finished in 4 minutes 23 seconds real runtime, using ~712% CPU.
That's ~48% more CPU usage and finishing in <58% of the time (being more than 74% faster.)