[Isolate.exit] Unpredictable performance.

[modulovalue]

This issue is about the efficiency guarantees of the new Isolate.exit feature.

Isolate.exit (via #36097) as a possible solution to #40653 seems to work ~50% of the time.

The following example uses the new Isolate.exit functionality to encode and decode json on a different isolate to not drop any frames (Timer.tick is used as a proxy for frames).

Code

import 'dart:async';
import 'dart:convert';
import 'dart:isolate';
import 'dart:math';

Future<void> main() async {
  for (int i = 0; i < 10; i++) {
    await run();
  }
}

Future<void> run() async {
  final frames = <int>[];
  final timer = Timer.periodic(
    const Duration(milliseconds: frameDurationIsMS),
    (final timer) => frames.add(timer.tick),
  );
  final jsonString = () {
    final rnd = Random();
    final map = <String, dynamic>{
      for (int i = 0; i < 500000; i++)
        i.toString(): [
          rnd.nextInt(1000),
          () {
            final rand = Random();
            final codeUnits = List.generate(
              10,
              (final index) => rand.nextInt(33) + 89,
            );
            return String.fromCharCodes(codeUnits);
          }()
        ],
    };
    return json.encode(map);
  }();
  final map = await runAsyncOperation<dynamic>(
    description: "json.decode",
    operation: () => asyncCompute<String, dynamic>(
      fn: json.decode,
      input: jsonString,
    ),
    getTimerTick: () => timer.tick,
  );
  await Future<void>(() {});
  final encodedMap = await runAsyncOperation<dynamic>(
    description: "json.encode",
    operation: () => asyncCompute<Map<dynamic, dynamic>, String>(
      fn: json.encode,
      input: map.result as Map<dynamic, dynamic>,
    ),
    getTimerTick: () => timer.tick,
  );
  timer.cancel();
  output(
    ops: [
      map,
      encodedMap,
    ],
    ticks: frames,
  );
}

Future<O> asyncCompute<I, O>({
  required final FutureOr<O> Function(I) fn,
  required final I input,
}) async {
  final receivePort = ReceivePort();
  final inbox = StreamIterator<dynamic>(
    receivePort,
  );
  await Isolate.spawn<_IsolateMessage<I, O>>(
    (final message) => Isolate.exit(
      message.sendPort,
      message.fn(
        message.input,
      ),
    ),
    _IsolateMessage(
      sendPort: receivePort.sendPort,
      fn: fn,
      input: input,
    ),
  );
  final movedNext = await inbox.moveNext();
  assert(
    movedNext,
    "Call to moveNext is expected to return true.",
  );
  final typedResult = inbox.current as O;
  receivePort.close();
  await inbox.cancel();
  return typedResult;
}

class _IsolateMessage<I, O> {
  final SendPort sendPort;
  final FutureOr<O> Function(I) fn;
  final I input;

  const _IsolateMessage({
    required final this.sendPort,
    required final this.fn,
    required final this.input,
  });
}

const int frameDurationIsMS = 1000 ~/ 120;

Future<Operation<T>> runAsyncOperation<T>({
  required final String description,
  required final FutureOr<T> Function() operation,
  required final int Function() getTimerTick,
}) async {
  final startTick = getTimerTick();
  final value = await operation();
  final endTick = getTimerTick();
  return Operation<T>(
    description: description,
    frameInfo: FrameInfo(
      startTick: startTick,
      endTick: endTick,
    ),
    result: value,
  );
}

void output({
  required final List<Operation<Object?>> ops,
  required final List<int> ticks,
}) {
  print("== Operation Info ==");
  print(
    "Operation".padRight(30) + "Start Frame".padRight(30) + "End Frame".padRight(30),
  );
  for (final op in ops) {
    print(
      _operationToText(
        operation: op,
      ),
    );
  }
  print("== Frame Info ==");
  print("Skipped Frames".padRight(30) + "Frame Range".padRight(30));
  for (final skippedFrame in _findSkippedFrames(
    frames: ticks,
  )) {
    print(
      ((skippedFrame.endTick - skippedFrame.startTick).toString()).padRight(30) +
          (skippedFrame.startTick.toString() + " to " + skippedFrame.endTick.toString()).padRight(30),
    );
  }
}

String _operationToText<T>({
  required final Operation<T> operation,
}) =>
    operation.description.padRight(30) +
    (operation.frameInfo.startTick.toString()).padRight(30) +
    (operation.frameInfo.endTick.toString()).padRight(30);

class Operation<T> {
  final String description;
  final FrameInfo frameInfo;
  final T result;

  const Operation({
    required final this.description,
    required final this.frameInfo,
    required final this.result,
  });
}

List<FrameInfo> _findSkippedFrames({
  required final List<int> frames,
}) {
  final skippedFrames = <FrameInfo>[];
  frames.fold<int?>(
    null,
    (final previousValue, final element) {
      if (previousValue == null) {
        return element;
      } else if (previousValue + 1 != element) {
        skippedFrames.add(
          FrameInfo(
            startTick: previousValue,
            endTick: element,
          ),
        );
      } else {
        return element;
      }
    },
  );
  return skippedFrames;
}

class FrameInfo {
  final int startTick;
  final int endTick;

  const FrameInfo({
    required final this.startTick,
    required final this.endTick,
  });
}

Output

/usr/local/opt/dart-beta/libexec/bin/dart --version
Dart SDK version: 2.15.0-178.1.beta (beta) (Tue Oct 12 11:11:28 2021 +0200) on "macos_x64"

/usr/local/opt/dart-beta/libexec/bin/dart snippet.dart
snippet.dart: Warning: Interpreting this as package URI, (...)
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             255                           
json.encode                   257                           347                           
== Frame Info ==
Skipped Frames                Frame Range                   
3                             132 to 135                    
4                             149 to 153                    
4                             159 to 163                    
2                             170 to 172                    
5                             175 to 180                    
4                             193 to 197                    
3                             202 to 205                    
2                             255 to 257                    
2                             337 to 339                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             228                           
json.encode                   234                           337                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             128 to 130                    
4                             141 to 145                    
3                             151 to 154                    
3                             166 to 169                    
2                             180 to 182                    
6                             228 to 234                    
2                             325 to 327                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             225                           
json.encode                   225                           311                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             122 to 124                    
2                             131 to 133                    
5                             142 to 147                    
4                             171 to 175                    
3                             180 to 183                    
44                            225 to 269                    
2                             300 to 302                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             225                           
json.encode                   226                           325                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             126 to 128                    
4                             139 to 143                    
3                             149 to 152                    
3                             163 to 166                    
2                             177 to 179                    
58                            226 to 284                    
2                             312 to 314                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             227                           
json.encode                   227                           315                           
== Frame Info ==
Skipped Frames                Frame Range                   
3                             122 to 125                    
2                             132 to 134                    
5                             143 to 148                    
4                             172 to 176                    
2                             181 to 183                    
46                            227 to 273                    
2                             304 to 306                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             224                           
json.encode                   225                           324                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             125 to 127                    
3                             138 to 141                    
4                             147 to 151                    
3                             162 to 165                    
3                             176 to 179                    
59                            225 to 284                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             225                           
json.encode                   226                           313                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             122 to 124                    
2                             131 to 133                    
4                             143 to 147                    
4                             172 to 176                    
2                             181 to 183                    
45                            226 to 271                    
2                             303 to 305                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             226                           
json.encode                   231                           329                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             126 to 128                    
4                             139 to 143                    
4                             149 to 153                    
3                             164 to 167                    
2                             178 to 180                    
5                             226 to 231                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             224                           
json.encode                   224                           311                           
== Frame Info ==
Skipped Frames                Frame Range                   
3                             121 to 124                    
2                             131 to 133                    
5                             142 to 147                    
4                             171 to 175                    
2                             180 to 182                    
45                            224 to 269                    
2                             301 to 303                    
== Operation Info ==
Operation                     Start Frame                   End Frame                     
json.decode                   0                             226                           
json.encode                   231                           330                           
== Frame Info ==
Skipped Frames                Frame Range                   
2                             127 to 129                    
5                             139 to 144                    
3                             150 to 153                    
3                             164 to 167                    
3                             178 to 181                    
5                             226 to 231      

The Frame Info section shows that some runs caused ~40 dropped frames and some didn't. I expected to see no large ranges of dropped frames.

[mkustermann]

@modulovalue Some colleagues also looked into your example, rewrote it a little and measured, see https://gist.github.com/mit-mit/ffa606e17569cecbd2c47c234ac1be21

I've looked at that particular example already, and come to the following conclusion:

The benchmark itself produces a 14 MB string and then decodes that into 50+ MB in-memory representation of that JSON string. Doing so will create a lot of objects that the garbage collector needs to churn through. Especially the JSON decoding of such a large message is a bit of a worst case scenario in a generational GC - because objects will be created in young generation, survive, need to be copied & promoted to old space.

Our young generation collections are stop-the-world. Usually they are very quick, due to the generational hypothesis holding (i.e. most objects die young). Though in this example it doesn't hold.

BUT: The situation in Flutter is slightly different, because Flutter collects the young generation often before it's actually full (it does so in-between frames if there's idle time). Doing so will reduce those pause times. In the standalone VM this doesn't happen.

There is an additional very long pause in this particular benchmark caused by waiting for a concurrent marking of old-space to finish. This pause time is probably feasible to address (I've filed
#47492 for this, @rmacnak-google has some ideas in this area).

So in summary: Those pause times are due to GC. The work for #36097 removed the 50MB of object allocations on the receiver side (we no longer pay that cost), but all isolates can have pauses due to GC.

[bsutton]

Not certain I should be adding to this issue as I don't think my issue is GC but does related to unexpected lag with a call to Isolate.exit.

Dart SDK version: 2.19.5 (stable) (Mon Mar 20 17:09:37 2023 +0000) on "linux_x64"

From the documentation:

Further, the receiving isolate will in most cases be able to receive the message in constant time.

I read this as; the time to exit and return data should be consistent regardless of the size of the data being returned.

I've written a test to explore this:

import 'dart:isolate';

void main() async {
  await test(size: 1);
  await test(size: 10);
  await test(size: 20);
  await test(size: 30);
  await test(size: 40);
  await test(size: 50);
  await test(size: 60);
  await test(size: 70);
  await test(size: 80);
  await test(size: 90);
  await test(size: 100);
}

Future<void> test({required int size}) async {
  final result = await Isolate.run(() {
    // allocate size * MB.
    final list = List.filled(1024 * 1024 * size, 0);
    return Tuple(DateTime.now(), list);
  });
  final completed = DateTime.now();
  final interval = completed.difference(result.t1);
  print('Time for Isolate.exit size: $size, ms:  ${interval.inMilliseconds} ');
  print('');
}

class Tuple<T1, T2> {
  Tuple(this.t1, this.t2);

  T1 t1;
  T2 t2;
}

This is a fairly typical run of the benchmark:

Time for Isolate.exit size: 1, ms:  2 

Time for Isolate.exit size: 10, ms:  9 

Time for Isolate.exit size: 20, ms:  17 

Time for Isolate.exit size: 30, ms:  45 

Time for Isolate.exit size: 40, ms:  33 

Time for Isolate.exit size: 50, ms:  73 

Time for Isolate.exit size: 60, ms:  49 

Time for Isolate.exit size: 70, ms:  103 

Time for Isolate.exit size: 80, ms:  66 

Time for Isolate.exit size: 90, ms:  128 

Time for Isolate.exit size: 100, ms:  82 

Whilst we have some lumps, there is a fairly linear relationship between the size of the memory allocated and the time it
takes isolate.exit to return it.
I would expects some bumps (due to gc) but I wouldn't expect the linear relationship we are seeing.

[mkustermann]

Whilst we have some lumps, there is a fairly linear relationship between the size of the memory allocated and the time it takes isolate.exit to return it.

In general Isolate.exit() is just like SendPort.send() a O(n) operation, i.e. linear in message size. That's because it has to verify that the message being sent doesn't contain objects that are unsendable. Though compared to SendPort.send() it does avoid the copy.

This is vaguely mentioned in the API docs of Isolate.exit() as: The system may be able to send this final message more efficiently than normal port communication between live isolates. In these cases this final message object graph will be reassigned to the receiving isolate without copying.

As part of #46752 there's a bullet point:

• Explore making send-and-exit O(1) - transferring receive port ownership as well

The issue right now is that certain native objects (e.g. sockets, timers, ...) cannot be sent or moved from isolate to isolate.

[bsutton]

That is disappointing. I would suggest the current documentation is misleading in that it describes isolate.exit as operating in constant time, which clearly it doesn't. Perhaps we could get this updated. I was rather excited by isolate.exit but it appears we are still left with isolates being of very limited utility given any sizable response will cause frame drops. Oh but for a thread.

…

On Fri, 24 Mar 2023, 8:10 pm Martin Kustermann, ***@***.***> wrote: Whilst we have some lumps, there is a fairly linear relationship between the size of the memory allocated and the time it takes isolate.exit to return it. In general Isolate.exit() is just like SendPort.send() a O(n) operation, i.e. linear in message size. That's because it has to verify that the message being sent doesn't contain objects that are unsendable. Though compared to SendPort.send() it does avoid the copy. This is vaguely mentioned in the API docs of Isolate.exit() as: *The system may be able to send this final message more efficiently than normal port communication between live isolates. In these cases this final message object graph will be reassigned to the receiving isolate without copying.* As part of #46752 <#46752> there's a bullet point: - *Explore making send-and-exit O(1) - transferring receive port ownership as well* The issue right now is that certain native objects (e.g. sockets, timers, ...) cannot be sent or moved from isolate to isolate. — Reply to this email directly, view it on GitHub <#47508 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAG32OB7CENRG55WC4BYSDTW5VQJVANCNFSM5GLEUNIA> . You are receiving this because you commented.Message ID: ***@***.***>

[mraleph]

@bsutton the O(n) overhead is entirely on the sending side, which does verification inside Isolate.exit call. Documentation does not mention that, but it correctly says that receiving side pays only O(1) per message. Your benchmark is measuring both the cost of Isolate.exit and the cost of receiving the message. So you see both sending and receiving costs which add up to O(n) + O(1) = O(n). If you want to measure just receiving costs you could set a timer which fires, say, every 10ms in the main isolate and then observe that there should be no significant drift between events even when you send large payloads.

That being said - building large payloads likely comes with some GC costs (e.g. due to the cost of evacuation of large number of survivors from the nursery or due to GC inability to make appropriate progress when allocation rate is too high) and GCs will pause all isolates in a group.

[modulovalue]

That is disappointing.

@bsutton an alternative solution to this issue is to allocate unmanaged memory via ffi and to pass around a pointer to that memory between isolates (see: #50457).

---

As part of #46752 there's a bullet point:

• Explore making send-and-exit O(1) - transferring receive port ownership as well

This sounds very exciting to me. @mkustermann, thank you for the update (and your work on these issues!).

Is the work on making send-and-exit O(1) intended to help with the "skipped frames" issue here? (I've ran the code in the issue description and it continues to report some skipped frames.)

[mkustermann]

Is the work on making send-and-exit O(1) intended to help with the "skipped frames" issue here? (I've ran the code in the issue description and it continues to report some skipped frames.)

The pauses may still be GC related (see my older comment at #47508 (comment)). Though we can investigate it again with newest VM - @aam could you have a look?

[modulovalue]

It looks like Michael has a more up-to-date benchmark related to this issue here.

[bsutton]

@mraleph

So I rewrote my own benchmark.

It spawns the isolate and then starts a loop checking for any gaps in the performance of the loop:

import 'dart:async';
import 'dart:isolate';

void main() async {
  await test(size: 1);
  await test(size: 10);
  await test(size: 20);
  await test(size: 30);
  await test(size: 40);
  await test(size: 50);
  await test(size: 60);
  await test(size: 70);
  await test(size: 80);
  await test(size: 90);
  await test(size: 100);
}

Future<void> test({required int size}) async {
  final completer = Completer<bool>();

  final future = Isolate.run(() {
    // allocate size MB.
    final list = List.filled(1024 * 1024 * size, 0);
    return Tuple(DateTime.now(), list);
  });

  unawaited(future.whenComplete(() {
    completer.complete(true);
  }));

  final frameDrops = <Duration>[];
  final stopwatch = Stopwatch()..start();

  while (!completer.isCompleted) {
    final elapsed = stopwatch.elapsed;
    if (elapsed > const Duration(milliseconds: 10)) {
      frameDrops.add(elapsed);
    }
    stopwatch.reset();
    // give async tasks a chance to run.
    await Future.delayed(const Duration(milliseconds: 1), () => null);
  }

  final completed = DateTime.now();
  final interval = completed.difference((await future).t1);
  print(
      'Time for Isolate.exit size: $size MB, ms:  ${interval.inMilliseconds} ');

  final totalDuration = frameDrops.isNotEmpty
      ? frameDrops.reduce((a, b) => a + b)
      : Duration.zero;

  final averageDuration = frameDrops.isNotEmpty
      ? Duration(
          microseconds: totalDuration.inMicroseconds ~/ frameDrops.length)
      : Duration.zero;

  if (frameDrops.isEmpty) {
    print('All Good');
  } else {
    print(
        'ERROR: frame drops: ${frameDrops.length} average duration: ${averageDuration.inMilliseconds}');
  }
  print('');
}

class Tuple<T1, T2> {
  Tuple(this.t1, this.t2);

  T1 t1;
  T2 t2;
}

Here is a test run:

Time for Isolate.exit size: 1 MB, ms:  4 
All Good

Time for Isolate.exit size: 10 MB, ms:  17 
All Good

Time for Isolate.exit size: 20 MB, ms:  34 
ERROR: frame drops: 1 average duration: 21

Time for Isolate.exit size: 30 MB, ms:  50 
ERROR: frame drops: 1 average duration: 34

Time for Isolate.exit size: 40 MB, ms:  69 
ERROR: frame drops: 1 average duration: 47

Time for Isolate.exit size: 50 MB, ms:  87 
ERROR: frame drops: 1 average duration: 56

Time for Isolate.exit size: 60 MB, ms:  104 
ERROR: frame drops: 1 average duration: 60

Time for Isolate.exit size: 70 MB, ms:  64 
ERROR: frame drops: 1 average duration: 60

Time for Isolate.exit size: 80 MB, ms:  140 
ERROR: frame drops: 1 average duration: 92

Time for Isolate.exit size: 90 MB, ms:  152 
ERROR: frame drops: 1 average duration: 102

Time for Isolate.exit size: 100 MB, ms:  174 
ERROR: frame drops: 2 average duration: 65

This test still shows a linear relationship.
I don't think this is a GC issue.
Each isolate does a single allocation. So the number of objects that need to be GC'd are constant for each test.
My assumption from this is that GC overhead should be constant.
Of course, the timing of when GC kicks in will be somewhat variable and the larger block allocations will be more likely to cause a GC.
So I did a run reversing the order of the sizes. The idea is that if we do the largest allocation first, we should be less likely to see a GC whilst it runs. My assumption (?) is that a single 100MB allocation shouldn't cause a GC to run.

Here are the results of the reversed run:

Time for Isolate.exit size: 101 MB, ms:  173 
ERROR: frame drops: 1 average duration: 111

Time for Isolate.exit size: 91 MB, ms:  153 
ERROR: frame drops: 1 average duration: 91

Time for Isolate.exit size: 81 MB, ms:  139 
ERROR: frame drops: 1 average duration: 90

Time for Isolate.exit size: 71 MB, ms:  125 
ERROR: frame drops: 2 average duration: 46

Time for Isolate.exit size: 61 MB, ms:  106 
ERROR: frame drops: 1 average duration: 69

Time for Isolate.exit size: 51 MB, ms:  84 
ERROR: frame drops: 1 average duration: 57

Time for Isolate.exit size: 41 MB, ms:  69 
ERROR: frame drops: 1 average duration: 46

Time for Isolate.exit size: 31 MB, ms:  53 
ERROR: frame drops: 1 average duration: 36

Time for Isolate.exit size: 21 MB, ms:  37 
ERROR: frame drops: 1 average duration: 24

Time for Isolate.exit size: 11 MB, ms:  16 
ERROR: frame drops: 1 average duration: 14

Time for Isolate.exit size: 1 MB, ms:  1 
All Good

As you can see we still have a linear relationship, which suggests this isn't a GC issue and that (at least some) of the performance cost is worn by the calling isolate.

[mraleph]

@bsutton What Dart version are you running? I get no frame drops neither on 2.19.5 nor 3.0.0-336.0.dev even if I go as high as 300 Mb.

[bsutton]

@mraleph
Dart SDK version: 2.19.5 (stable) (Mon Mar 20 17:09:37 2023 +0000) on "linux_x64"

[bsutton]

@mraleph
I am running it from the vscode debugger but I've just doen a second run from the cli and get the same results:

dart bin/simple.dart

[bsutton]

@mraleph
AMD® Ryzen 7 3700x 8-core processor × 16
AMD® Radeon rx 5500 xt
Memory: 32.0 GiB
Ubuntu 22.04.2 LTS (64 bits)