Dart-Code
Isolates created at the start of a Flutter app are sometimes not correctly resumed during startup/hot restart (maybe Android?)
Describe the bug When I launch my app I spawn several isolates. If I then add a breakpoint my debugger freezes and says "Paused on entry" on some of the isolates. If I instead wait until all my isolates are spawned and then add my breakpoint it works as expected. I have only seen the bug on android and I was not able to reproduce it for a dart console application.
To Reproduce
- Create new flutter app and and edit main.dart to:
import 'dart:isolate';
import 'dart:math';
void main() async {
List<ReceivePort> isolates = [];
for (int i = 0; i < 10; i++) {
final receivePort = ReceivePort();
Isolate.spawn(calculateUsingIsolate, receivePort.sendPort);
isolates.add(receivePort);
}
List<dynamic> responses = await Future.wait(isolates.map((e) => e.first));
print("Isolates are ready: $responses" ); // BREAKPOINT HERE
}
Future<void> calculateUsingIsolate(SendPort sendPort) async {
int result = Random().nextInt(10);
await Future.delayed(Duration(seconds: result));
sendPort.send(result);
}
- Run code without breakpoints and see that it correctly prints output.
- Set a breakpoint on line 12, reload and see that it does not reach the breakpoint and that the call stack reports it to be paused.
Expected behavior I expected breakpoints not to interfere with the execution of isolates.
Screenshots
Please complete the following information:
- Operating System and version: Linux Mint 22.1 Xia
- VS Code version: 1.105.1
- Dart extension version: 3.124.0
- Dart/Flutter SDK version: 3.10.1 / 3.38.3
- Target device: Samsung Galaxy Tab Active 3
I can reproduce breakpoints showing as "Paused on Entry", however the behaviour appears to be the same both with/without the breakpoint (that is, isolates show incorrectly as paused, however if I wait, they do complete in both cases).
I will investigate why they're showing as paused-on-entry, but since your behaviour appears different, could you do the following:
- Open the command palette (F1)
- Run the Preferences: Open Workspace Settings (JSON) command
- Add
"dart.dapLogFile": "logs/dap.txt"to the json - Re-run your example to reproduce the issue
- Wait for at least 30s after you think it is not completing (to help identify if something is running very slowly or timing out)
- Stop the debug session
- Attach the
logs/dap.txtfile here (after ensuring there's nothing sensitive in it)
Thanks!
Reviewing the log, it appears that the DAP traffic is correct and the threads were all resumed:
This suggests a bug in VS Code - we have reported this before in https://github.com/microsoft/vscode/issues/238591 but it appeared fixed, but I wonder if there are still timing problems. I will try to isolate a repro to file with VS Code.
That issue is purely cosmetic though (it's just showing the wrong state). If you are seeing the behaviour change (eg. the isolates never actually run), then that's a different issue we also need to track down (and the log described above may help).
I've opened https://github.com/microsoft/vscode/issues/280933 about the bug with showing "Paused on Entry" with a repro in mock-debug.
I can reproduce breakpoints showing as "Paused on Entry", however the behaviour appears to be the same both with/without the breakpoint (that is, isolates show incorrectly as paused, however if I wait, they do complete in both cases).
I will investigate why they're showing as paused-on-entry, but since your behaviour appears different, could you do the following:
* Open the command palette (F1) * Run the **Preferences: Open Workspace Settings (JSON)** command * Add `"dart.dapLogFile": "logs/dap.txt"` to the json * Re-run your example to reproduce the issue * Wait for at least 30s after you think it is not completing (to help identify if something is running very slowly or timing out) * Stop the debug session * Attach the `logs/dap.txt` file here (after ensuring there's nothing sensitive in it)Thanks!
I still don't get to the breakpoint on the second run
Thanks for the log! Something does look wrong here - is it possible you could reproduce this while capturing a slightly different log which will include the Dart VM Service traffic?
- Open the command palette (
F1) - Run the Dart: Capture Debugging Logs command
- Re-run your example to reproduce the issue
- Wait for at least 30s after you think it is not completing (to help identify if something is running very slowly or timing out)
- Click Cancel on the logging notification to stop logging and open the log file
- Ensure nothing sensitive in the log and attach here or send to [email protected]
The log will be much larger because it'll run Flutter in verbose mode, and it will also capture the VM Service traffic.
I will try again at reproducing this - do you have any other devices or computers you can easily test to see if it might be specific to Linux and/or Android?
Thanks!
@mariusturftank I also noticed there are hot restarts in the most recent log file - can you confirm if the issue is only occurring when using hot restart?
Thanks for the log! Something does look wrong here - is it possible you could reproduce this while capturing a slightly different log which will include the Dart VM Service traffic?
* Open the command palette (`F1`) * Run the **Dart: Capture Debugging Logs** command * Re-run your example to reproduce the issue * Wait for at least 30s after you think it is not completing (to help identify if something is running very slowly or timing out) * Click **Cancel** on the logging notification to stop logging and open the log file * Ensure nothing sensitive in the log and attach here or send to [[email protected]](mailto:[email protected])The log will be much larger because it'll run Flutter in verbose mode, and it will also capture the VM Service traffic.
I will try again at reproducing this - do you have any other devices or computers you can easily test to see if it might be specific to Linux and/or Android?
Thanks!
I have tested it with dart cli, linux and android. I have only been able to reproduce on android on two separate devices (Tab Active 3 and Tab Active 5). I also managed to reproduce it with a different computer in a clean project.
Dart-Code-Log-2025-11-01 13-47-15.txt
@mariusturftank I also noticed there are hot restarts in the most recent log file - can you confirm if the issue is only occurring when using hot restart?
Yes, I tried to reproduce it by stopping and launching the app again (~10 times), but that didn't seem to cause the same issue. It seems to not be as consistent as I would like. Sometimes I need to hot restart a few times before it occurs.
Thanks! In the log file I can see that after the restart when we send the breakpoints to the new isolates, we call readyToResume but it doesn't appear that the isolate ever resumes.
@bkonyi in case you have any ideas - I'm trying to reproduce this locally, but I wonder if you can think of any reasons that we'd never see any isolate events after calling readyToResume. Here is the complete log for isolate 4481616764844163 extracted from the complete log (minus the ServiceExtensionAdded events since they're noisy):
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Isolate","event":{"type":"Event","kind":"IsolateStart","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068023}}}
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Isolate","event":{"type":"Event","kind":"IsolateRunnable","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068028}}}
[1:47:42 PM] ==> [VM] {"jsonrpc":"2.0","id":"78","method":"getIsolate","params":{"isolateId":"isolates/4481616764844163"}}
[1:47:42 PM] ==> [VM] {"jsonrpc":"2.0","id":"79","method":"setIsolatePauseMode","params":{"isolateId":"isolates/4481616764844163","exceptionPauseMode":"None"}}
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"PauseStart","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068028}}}
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","result":{"type":"Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544","startTime":1765198068020,"_heaps":{"new":{"type":"HeapSpace","name":"new","vmName":"Scavenger","collections":1,"avgCollectionPeriodMillis":525.506,"used":84608,"capacity":3670016,"external":32,"time":0.002177},"old":{"type":"HeapSpace","name":"old","vmName":"PageSpace","collections":0,"used":5655408,"capacity":7340032,"external":0,"time":0.0,"avgCollectionPeriodMillis":0.0}},"isolateFlags":[{"name":"is_system_isolate","valueAsString":"false"},{"name":"is_service_isolate","valueAsString":"false"},{"name":"is_kernel_isolate","valueAsString":"false"}],"runnable":true,"livePorts":1,"pauseOnExit":false,"_isReloading":false,"pauseEvent":{"type":"Event","kind":"PauseStart","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068028},"rootLib":{"type":"@Library","fixedId":true,"id":"libraries/@19456239","name":"","uri":"file:///home/marius/Documents/extra/freezing_breakpoint/example/dart_example.dart"},"_tagCounters":{"names":["Idle","LoadWait","VM","CompileOptimized","CompileUnoptimized","ClassLoading","CompileParseRegExp","Dart","DartInterpreted","GCNewSpace","GCOldSpace","Embedder","Runtime","Native"],"counters":[0,0,3,0,0,0,0,0,0,0,0,0,0,2]},"libraries":[{"type":"@Library","fixedId":true,"id":"libraries/@0150898","name":"dart.core","uri":"dart:core"},{"type":"@Library","fixedId":true,"id":"libraries/@1026248","name":"dart.isolate","uri":"dart:isolate"},{"type":"@Library","fixedId":true,"id":"libraries/@2408521","name":"dart.mirrors","uri":"dart:mirrors"},{"type":"@Library","fixedId":true,"id":"libraries/@3099033","name":"dart._compact_hash","uri":"dart:_compact_hash"},{"type":"@Library","fixedId":true,"id":"libraries/@4220832","name":"dart.collection","uri":"dart:collection"},{"type":"@Library","fixedId":true,"id":"libraries/@5048458","name":"dart.async","uri":"dart:async"},{"type":"@Library","fixedId":true,"id":"libraries/@6383715","name":"dart.developer","uri":"dart:developer"},{"type":"@Library","fixedId":true,"id":"libraries/@7320332","name":"nativewrappers","uri":"dart:nativewrappers"},{"type":"@Library","fixedId":true,"id":"libraries/@8027147","name":"dart.typed_data","uri":"dart:typed_data"},{"type":"@Library","fixedId":true,"id":"libraries/@9050071","name":"dart.ffi","uri":"dart:ffi"},{"type":"@Library","fixedId":true,"id":"libraries/@10040228","name":"dart._internal","uri":"dart:_internal"},{"type":"@Library","fixedId":true,"id":"libraries/@11003594","name":"dart.convert","uri":"dart:convert"},{"type":"@Library","fixedId":true,"id":"libraries/@12383281","name":"dart.math","uri":"dart:math"},{"type":"@Library","fixedId":true,"id":"libraries/@13168694","name":"dart._vmservice","uri":"dart:_vmservice"},{"type":"@Library","fixedId":true,"id":"libraries/@14398151","name":"dart.concurrent","uri":"dart:concurrent"},{"type":"@Library","fixedId":true,"id":"libraries/@15069316","name":"dart.io","uri":"dart:io"},{"type":"@Library","fixedId":true,"id":"libraries/@16463476","name":"dart._http","uri":"dart:_http"},{"type":"@Library","fixedId":true,"id":"libraries/@17065589","name":"dart.ui","uri":"dart:ui"},{"type":"@Library","fixedId":true,"id":"libraries/@18205832","name":"vmservice_io","uri":"dart:vmservice_io"},{"type":"@Library","fixedId":true,"id":"libraries/@19456239","name":"","uri":"file:///home/marius/Documents/extra/freezing_breakpoint/example/dart_example.dart"}],"breakpoints":[],"exceptionPauseMode":"None","_debuggerSettings":{"_exceptions":"none"},"extensionRPCs":["ext.dart.io.httpEnableTimelineLogging","ext.dart.io.getSocketProfile","ext.dart.io.socketProfilingEnabled","ext.dart.io.clearSocketProfile","ext.dart.io.getVersion","ext.dart.io.getHttpProfile","ext.dart.io.getHttpProfileRequest","ext.dart.io.clearHttpProfile"],"isolate_group":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false}},"id":"78"}
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"_DebuggerSettingsUpdate","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068097}}}
[1:47:42 PM] ==> [VM] {"jsonrpc":"2.0","id":"93","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/4481616764844163","scriptUri":"file:///home/marius/Documents/extra/freezing_breakpoint/example/dart_example.dart","line":12}}
[1:47:42 PM] <== [VM] {"jsonrpc":"2.0","method":"streamNotify","params":{"streamId":"Debug","event":{"type":"Event","kind":"BreakpointAdded","isolateGroup":{"type":"@IsolateGroup","id":"isolateGroups/209712231422544","name":"main.dart","number":"209712231422544","isSystemIsolateGroup":false},"isolate":{"type":"@Isolate","id":"isolates/4481616764844163","name":"calculateUsingIsolate","number":"4481616764844163","isSystemIsolate":false,"isolateGroupId":"isolateGroups/209712231422544"},"timestamp":1765198068163,"breakpoint":{"type":"Breakpoint","fixedId":true,"id":"breakpoints/1","enabled":true,"breakpointNumber":1,"resolved":true,"location":{"type":"SourceLocation","script":{"type":"@Script","fixedId":true,"id":"libraries/@19456239/scripts/file%3A%2F%2F%2Fhome%2Fmarius%2FDocuments%2Fextra%2Ffreezing_breakpoint%2Fexample%2Fdart_example.dart/19afe00f7dc","uri":"file:///home/marius/Documents/extra/freezing_breakpoint/example/dart_example.dart"},"tokenPos":405,"line":12,"column":59}}}}}
[1:47:42 PM] ==> [VM] {"jsonrpc":"2.0","id":"103","method":"readyToResume","params":{"isolateId":"isolates/4481616764844163"}}
[1:47:42 PM] ==> [VM] {"jsonrpc":"2.0","id":"107","method":"getStack","params":{"isolateId":"isolates/4481616764844163","limit":1}}
(the log continues until 1:48:29 PM, but there are no more occurrences of 4481616764844163)
@mariusturftank I'm sure the answer is no - but you don't have any other debugger attached to the app right? (eg. the DevTools debugger, or something else that might've used flutter attach)
I think I've been able to reproduce this using a physical Pixel 4a. But it doesn't seem to always require a hot restart, sometimes it just happens on the initial startup.
It seems slightly odd to see output like "Installing profile for com.dantup.dartcode_5829_f" when the app is already running though - not sure if that's normal.
Complete log for reference: Dart-Code-Log-2025-11-01 16-14-02.txt
@bkonyi I added some logging inside readyToResume inside DDS. It appears that one of the requests calls _resumeCommon which never completes, and then because of the mutex everything else queues up behind it:
_resumeCommon doesn't do much (just clear the resume approvals and then send resume to the VM) so I think debugging this further might require some poking around inside the VM Service.
I don't know if it's related, but I'll point out that the app used to repro this from above is being run via Flutter, but does not call runApp so it doesn't actually show any app. However, the main thread does await all of the isolates, so the it's not completing and terminating the app (at least not when this happens on the first run, as it often does for me).
Edit: Adding runApp(Placeholder()); to the top of main did not change the behaviour.
@bkonyi I've been running with a locally built engine to enable "--dart-flags=\"--trace_service --trace_service_pause_events --trace_debugger_stacktrace\"" however I'm not seeing any additional data anywhere (but I'm not sure where I'm supposed to be looking).
However, I did notice that when this fails, we're always sending getStack() get close to when we send readyToResume():
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"22","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/8426972181122039","scriptUri":"file:///D:/Dev/Test%20Projects/dartcode_5829_f/lib/main.dart","line":19}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"23","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/6591335184794703","scriptUri":"file:///D:/Dev/Test%20Projects/dartcode_5829_f/lib/main.dart","line":19}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"24","method":"addBreakpointWithScriptUri","params":{"isolateId":"isolates/8558144104817035","scriptUri":"file:///D:/Dev/Test%20Projects/dartcode_5829_f/lib/main.dart","line":19}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"25","method":"readyToResume","params":{"isolateId":"isolates/7967818485659407"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"26","method":"readyToResume","params":{"isolateId":"isolates/5606548613970223"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"27","method":"readyToResume","params":{"isolateId":"isolates/6270300650058019"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"28","method":"readyToResume","params":{"isolateId":"isolates/8426972181122039"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"29","method":"getStack","params":{"isolateId":"isolates/7967818485659407","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"30","method":"getStack","params":{"isolateId":"isolates/5606548613970223","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"31","method":"readyToResume","params":{"isolateId":"isolates/1681246748291835"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"32","method":"getStack","params":{"isolateId":"isolates/6270300650058019","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"33","method":"getStack","params":{"isolateId":"isolates/8426972181122039","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"34","method":"readyToResume","params":{"isolateId":"isolates/4076852524646731"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"35","method":"getStack","params":{"isolateId":"isolates/1681246748291835","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"36","method":"getStack","params":{"isolateId":"isolates/4076852524646731","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"37","method":"readyToResume","params":{"isolateId":"isolates/6591335184794703"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"38","method":"getStack","params":{"isolateId":"isolates/6591335184794703","limit":1}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"39","method":"readyToResume","params":{"isolateId":"isolates/2361381701895727"}}
[6:31:22 PM] [VmService] [Info] [dartcode_5829 (Pixel 4a)] ==> [VM] {"jsonrpc":"2.0","id":"40","method":"getStack","params":{"isolateId":"isolates/2361381701895727","limit":1}}
I tried suppressing this, and in quite a few runs, I have not reproduced the issue (even though it being very easy to repro when the getStack() call is sent). This isn't conclusive - it's possible this just alters the timing in some way - but can you think whether there might be anything in getStack() that might interfere with the resume (in a way that would cause a request to not complete, which would then hold the mutex lock in DDS)?
getStack() shouldn't be causing any sort of hang since it can be executed even when the isolate isn't paused. I'll dig a bit more into the VM's C++ code to see if I missed something.
For the output of the flags, you'll probably need to use logcat to see them since the VM just dumps everything to stderr and the tool probably doesn't pick them up.
getStack()shouldn't be causing any sort of hang since it can be executed even when the isolate isn't paused
Ah, I wasn't sure if it might have to pause it to read the stack atomically. Maybe it's just changing the timing a bit then.
There are ofc also multiple resumes coming in at the same time here - they're for different isolates, but is there anything that could stall/deadlock there? (I don't know what the implementation of resume looks like either).
For the output of the flags, you'll probably need to use
logcat
Aha, I'll do some more testing of this tomorrow - thanks!
@bkonyi unfortunately (assuming running adb logcat with no flags is the right thing), nothing seems to show up their either. Here's the full log starting from "The Dart VM service is listening..." until many seconds after the hang occurred.
I do wonder if those flags I set are working correctly (although it does fail saying they're disallowed when I don't use my custom engine, so they are at least getting to the code that validates them).
12-11 10:51:37.448 8473 8513 I flutter : The Dart VM service is listening on http://127.0.0.1:43381/HwIPgH22ZsQ=/
12-11 10:51:37.519 8473 8473 W dartcode_5829_f: Accessing hidden method Landroid/view/accessibility/AccessibilityNodeInfo;->getSourceNodeId()J (unsupported,test-api, reflection, allowed)
12-11 10:51:37.519 8473 8473 W dartcode_5829_f: Accessing hidden method Landroid/view/accessibility/AccessibilityRecord;->getSourceNodeId()J (unsupported, reflection, allowed)
12-11 10:51:37.519 8473 8473 W dartcode_5829_f: Accessing hidden field Landroid/view/accessibility/AccessibilityNodeInfo;->mChildNodeIds:Landroid/util/LongArray; (unsupported, reflection, allowed)
12-11 10:51:37.519 8473 8473 W dartcode_5829_f: Accessing hidden method Landroid/util/LongArray;->get(I)J (unsupported, reflection, allowed)
12-11 10:51:37.531 8473 8473 D FlutterRenderer: Width is zero. 0,0
12-11 10:51:37.545 8473 8473 D CompatibilityChangeReporter: Compat change id reported: 237531167; UID 10234; state: DISABLED
12-11 10:51:37.553 8473 8491 W Parcel : Expecting binder but got null!
12-11 10:51:37.557 1694 1734 D CoreBackPreview: Window{5921839 u0 com.dantup.dartcode_5829_f/com.dantup.dartcode_5829_f.MainActivity}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.IOnBackInvokedCallback$Stub$Proxy@56c4fdf, mPriority=0}
12-11 10:51:37.559 8473 8473 I Choreographer: Skipped 35 frames! The application may be doing too much work on its main thread.
12-11 10:51:37.604 8473 8473 D FlutterRenderer: Width is zero. 0,0
12-11 10:51:37.613 8473 8473 D FlutterJNI: Sending viewport metrics to the engine.
12-11 10:51:37.623 698 698 I SDM : HWCDisplay::GetColorModeCount: Supported color mode count = 3
12-11 10:51:37.625 8473 8491 E OpenGLRenderer: Unable to match the desired swap behavior.
12-11 10:51:38.018 5658 5658 W ThreadPoolForeg: type=1400 audit(0.0:228): avc: denied { write } for name="traced_producer" dev="tmpfs" ino=13021 scontext=u:r:gmscore_app:s0:c512,c768 tcontext=u:object_r:traced_producer_socket:s0 tclass=sock_file permissive=0 app=com.google.android.gms
12-11 10:51:38.372 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 0] [i 0]
12-11 10:51:38.398 8473 8473 I Choreographer: Skipped 47 frames! The application may be doing too much work on its main thread.
12-11 10:51:38.405 8473 8473 D FlutterJNI: Sending viewport metrics to the engine.
12-11 10:51:39.125 3493 3493 W ThreadPoolForeg: type=1400 audit(0.0:229): avc: denied { write } for name="traced_producer" dev="tmpfs" ino=13021 scontext=u:r:gmscore_app:s0:c512,c768 tcontext=u:object_r:traced_producer_socket:s0 tclass=sock_file permissive=0 app=com.google.android.gms
12-11 10:51:39.129 1412 1412 W adbd : timeout expired while flushing socket, closing
12-11 10:51:39.148 8473 8482 I dartcode_5829_f: Compiler allocated 4413KB to compile void android.view.ViewRootImpl.performTraversals()
12-11 10:51:39.710 8473 8473 I flutter : Spawning isolates...
12-11 10:51:39.733 8473 8473 I flutter : Waiting for isolates...
12-11 10:51:41.396 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 0] [i 1]
12-11 10:51:41.658 1694 4970 D OomAdjuster: Not killing cached processes
12-11 10:51:44.427 1694 2397 D ConnectivityService: NetReassign [no changes] [c 1] [a 0] [i 4]
12-11 10:51:46.747 1694 1886 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
12-11 10:51:46.759 1694 1882 D OomAdjuster: Not killing cached processes
12-11 10:51:46.830 1694 1886 D CompatibilityChangeReporter: Compat change id reported: 181136395; UID 10234; state: DISABLED
12-11 10:51:46.830 1694 1886 D CompatibilityChangeReporter: Compat change id reported: 174042936; UID 10234; state: DISABLED
12-11 10:51:46.836 3954 3954 I cows : onStop
12-11 10:51:46.842 2874 4025 D OneSearchSuggestProvider: Shut down the binder channel
12-11 10:51:46.843 2874 2901 I s.nexuslauncher: oneway function results for code 2 on binder at 0xb400007cff7d0960 will be dropped but finished with status UNKNOWN_TRANSACTION
12-11 10:51:47.450 1694 2397 D ConnectivityService: NetReassign [no changes] [c 1] [a 0] [i 4]
Edit: I also tried logcat *:V but there doesn't seem to be anything extra:
12-11 10:56:09.392 8678 8721 I flutter : The Dart VM service is listening on http://127.0.0.1:40933/9RerEEGToyA=/
12-11 10:56:09.427 8678 8678 W dartcode_5829_f: Accessing hidden method Landroid/view/accessibility/AccessibilityNodeInfo;->getSourceNodeId()J (unsupported,test-api, reflection, allowed)
12-11 10:56:09.427 8678 8678 W dartcode_5829_f: Accessing hidden method Landroid/view/accessibility/AccessibilityRecord;->getSourceNodeId()J (unsupported, reflection, allowed)
12-11 10:56:09.427 8678 8678 W dartcode_5829_f: Accessing hidden field Landroid/view/accessibility/AccessibilityNodeInfo;->mChildNodeIds:Landroid/util/LongArray; (unsupported, reflection, allowed)
12-11 10:56:09.427 8678 8678 W dartcode_5829_f: Accessing hidden method Landroid/util/LongArray;->get(I)J (unsupported, reflection, allowed)
12-11 10:56:09.438 8678 8678 D FlutterRenderer: Width is zero. 0,0
12-11 10:56:09.450 8678 8678 D CompatibilityChangeReporter: Compat change id reported: 237531167; UID 10234; state: DISABLED
12-11 10:56:09.454 8678 8698 W Parcel : Expecting binder but got null!
12-11 10:56:09.458 1694 3361 D CoreBackPreview: Window{a932569 u0 com.dantup.dartcode_5829_f/com.dantup.dartcode_5829_f.MainActivity}: Setting back callback OnBackInvokedCallbackInfo{mCallback=android.window.IOnBackInvokedCallback$Stub$Proxy@d29988f, mPriority=0}
12-11 10:56:09.462 8678 8678 I Choreographer: Skipped 32 frames! The application may be doing too much work on its main thread.
12-11 10:56:09.508 8678 8678 D FlutterRenderer: Width is zero. 0,0
12-11 10:56:09.516 8678 8678 D FlutterJNI: Sending viewport metrics to the engine.
12-11 10:56:09.525 698 698 I SDM : HWCDisplay::GetColorModeCount: Supported color mode count = 3
12-11 10:56:09.527 8678 8698 E OpenGLRenderer: Unable to match the desired swap behavior.
12-11 10:56:10.310 8678 8678 I Choreographer: Skipped 47 frames! The application may be doing too much work on its main thread.
12-11 10:56:10.321 8678 8678 D FlutterJNI: Sending viewport metrics to the engine.
12-11 10:56:10.864 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 0] [i 0]
12-11 10:56:10.865 1412 1412 W adbd : timeout expired while flushing socket, closing
12-11 10:56:11.061 8678 8687 I dartcode_5829_f: Compiler allocated 4413KB to compile void android.view.ViewRootImpl.performTraversals()
12-11 10:56:11.711 8678 8678 I flutter : Spawning isolates...
12-11 10:56:11.736 8678 8678 I flutter : Waiting for isolates...
12-11 10:56:13.897 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 1] [i 2]
12-11 10:56:16.923 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 0] [i 4]
12-11 10:56:18.690 1694 1886 W ActivityTaskManager: Launch timeout has expired, giving up wake lock!
12-11 10:56:18.769 1694 1886 D CompatibilityChangeReporter: Compat change id reported: 181136395; UID 10234; state: DISABLED
12-11 10:56:18.770 1694 1886 D CompatibilityChangeReporter: Compat change id reported: 174042936; UID 10234; state: DISABLED
12-11 10:56:18.775 3954 3954 I cows : onStop
12-11 10:56:18.777 2874 4025 D OneSearchSuggestProvider: Shut down the binder channel
12-11 10:56:18.786 2874 3095 I s.nexuslauncher: oneway function results for code 2 on binder at 0xb400007cff7c92e0 will be dropped but finished with status UNKNOWN_TRANSACTION
12-11 10:56:19.950 1694 2397 D ConnectivityService: NetReassign [no changes] [c 0] [a 1] [i 3]
@bkonyi this is interesting... I added another print to happen after 3 seconds:
print('Waiting for isolates...');
Future.delayed(
const Duration(seconds: 3),
).then((_) => print('Isolates should have finished by now!'));
List<dynamic> responses = await Future.wait(isolates.map((e) => e.first));
print("Isolates are done: $responses"); // BREAKPOINT HERE
I thought this would let me ensure I have the full logcat output and it wasn't just buffered/delayed. However when the issue occurs, "Isolates should have finished by now" is never printed. This surprises me, because even if the spawns isolates never start/complete, I would've expected this 3s timer to still fire and print?
When terminating the app, I also see this:
[ +25 ms] I/flutter ( 8846): Waiting for isolates...
[+71677 ms] DevFS: Deleting filesystem on the device (file:///data/user/0/com.dantup.dartcode_5829_f/code_cache/dartcode_5829_fNDXXHK/dartcode_5829_f/)
[ +255 ms] Ignored error while cleaning up DevFS: TimeoutException after 0:00:00.250000: Future not completed
So I wonder whether the issue is more than just the isolates themselves not running?
I'm not sure how to debug any further, so if you have any ideas (or have an Android device and want to try to repro), lmk!
That's strange... It's like the event loop is being blocked somehow. I can try to take a look sometime next week when I find some time.
@bkonyi great, thank you! FWIW I had much better luck reproducing it from my Windows PC, but I was able to reproduce it on the Mac at a lower frequency (both using the same physical Android device, but I presume the host may play a part in the timing since that's where DAP/DDS are).