Async stack traces are missing frames before the first async gap for all typical Flutter use cases

[jacob314]

It turns out Dart stack traces have always been incomplete for the typical Flutter use case of an async method triggered by code running on the event loop rather than async code triggered from main. This impacts both Stacktrace.current and the stacktraces returned by the VMService.

Command line Dart app repro:
https://github.com/jacob314/stack_trace_repro/blob/main/console-simple/bin/console_simple.dart

This repro uses Timer to simulate running some code on the event loop as in a Flutter application. If you attempt to repro using purely async methods you will not be able to as async stack traces work great for that case.

dart run bin/console_simple.dart
Notice that none of the stack traces include methods before the the first .
For Flutter this makes debugging sync code difficult as you cannot see what the code from your Flutter widget was that triggered the async code (e.g. what is the call stack from clicking a button until the first async gap?).
For example, when debugging devtools I often see stack traces that look like

where I have no ide what method in my code called blockWhileInProgress.

Output from the Dart command line repro:

Start main. #0      main (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:54:35)
#1      _delayEntrypointInvocation.<anonymous closure> (dart:isolate-patch/isolate_patch.dart:281:32)
#2      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:184:12)

nonAsyncFunc. Stack trace correctly includes handleTimeout.
    It is correct this stacktrace does not include main as Timer was used rather than
    aysnc.

    #0      nonAsyncFunc (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:15:18)
#1      handleTimeout (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:7:3)
#2      Timer._createTimer.<anonymous closure> (dart:async-patch/timer_patch.dart:18:15)
#3      _Timer._runTimers (dart:isolate-patch/timer_impl.dart:395:19)
#4      _Timer._handleMessage (dart:isolate-patch/timer_impl.dart:426:5)
#5      _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:184:12)

Func1. Stack trace should be:
  func1
  <asynchronous suspension>
  nonAsyncFunc
  useATimerToGetOnTheEventLoopWithoutAsync
  ...

  But is instead:
  #0      func1 (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:47:16)
<asynchronous suspension>

  
Func2. Stack trace should be:
  func2
  <asynchronous suspension>
  func1
  <asynchronous suspension>
  nonAsyncFunc
  useATimerToGetOnTheEventLoopWithoutAsync
  ...

  But is instead:
  #0      func2 (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:31:16)
<asynchronous suspension>
#1      func1 (file:///Users/jacobr/git/stack_trace_repro/console-simple/bin/console_simple.dart:50:3)
<asynchronous suspension>

[jacob314]

Fyi @bkonyi @a-siva
This user hasn't been reported by customers not because it isn't an issue but because our Flutter users don't know to expect full async stack traces.

[mraleph]

This is a known limitation of the current approach to async stack traces, see go/dart-10x-faster-async

Theoretically we could collect a stack traces when we call async function without awaiting, but that is going to cost in terms of performance.

/cc @mkustermann @cskau-g

[jacob314]

+100 to collecting the stack trace even when the sync function is not awaited even if there is some performance overhead.
I only really care about seeing the additional frames in debug builds.

@natebosch also filed a bug likely due to the same change in async stack trace behavior.
#46326

[Jet132]

100% agree. It should at least be a runtime flag as currently, the stack trace is practically useless for some async code.

There is stack_trace but I'm against using additional packages for what should be a standard language feature. Funny enough you guys are the authors of the above package so you must have this problem too.

[lpylpyleo]

I hope we can get full stack trace when the application is running in debug mode at least.

[mkustermann]

We do have explicit points in the code when we suspend an async frame. We could let that code test whether the caller is non-async/async* and if so, capture the stack in the async functions state, making it available to the stack walker.

Though it would make every async function a bit slower and sync->async calls quite a bit slower (capturing stack trace is expensive).

One could avoid always paying the cost and instead make it explicit in the code by adding e.g. a unawaited function call that adds a dummy listener with captured stack and the stack walker could recognize the dummy listener object.

unawaited(foo());

The analyzer even has a unawaited_futures hint that suggests to call unawaited from dart:async.

/cc @alexmarkov wdyt?

[alexmarkov]

@mkustermann Stack trace collection during await is likely to affect performance, even if we somehow test the caller (which is also not free). unawaited will not help as it is not used if the code actually uses Future returned from async function (for example if Future.then or Future.wait is called on the resulting future), and I think this is the most common case for sync->async transitions.

We used to have an option (--causal_async_stacks) which provided more detailed stack traces at the expense of slower async/await. Maybe we should restore it / implement something like that to provide better utility in debug mode (indeed, history repeats itself). With current implementation of lazy async stack traces we only need to collect stack trace up to the first async caller, so hopefully it would be faster compared to the old option.

[mkustermann]

unawaited will not help as it is not used if the code actually uses Future returned from async function (for example if Future.then or Future.wait is called on the resulting future), and I think this is the most common case for sync->async transitions.

Our stack trace code does unwind across Future.wait and Future.then, see e.g. this test.
So the main scenario to me seems: An async function is called but it's returned future is unused (which is the case the unawaited hint is checking for)

We used to have an option (--causal_async_stacks) which provided more detailed stack traces at the expense of slower async/await. Maybe we should restore it / implement something like that to provide better utility in debug mode (indeed, history repeats itself).

Going back to what we had (eagerly capturing stack traces via runtime calls for every single async function invocation) is an absolute no-go. So history will not repeat :-)

Capturing stacks eagerly for sync->async transitions (or the subset of cases where the returned Future is discarded) may be considered. If we do that, the question (as raised above) would be whether to pay for this detection always or only for users of unawaited and encourage turning on the lint in the ecosystem.

[alexmarkov]

Our stack trace only scans asynchronous awaiters after reaching the first async. All synchronous calls are omitted from the stack trace after the first async (they are technically already gone at that point).

For example (without unawaited futures):

void printStackTrace() {
  print(StackTrace.current);
}

Future<void> baz() async {
  await null;
  printStackTrace();
}

Future<void> bar() {
  return baz().then((_) {
    print('bar');
  });
}

Future<void> foo() {
  return bar();
}

main() async {
  await foo();
}

#0      printStackTrace (file:///.../foo.dart:3:20)
#1      baz (file:///.../foo.dart:8:3)
<asynchronous suspension>
#2      main (file:///.../foo.dart:22:3)
<asynchronous suspension>

So, I would not focus solely on supporting stack trace for the unawaited case / unused Future. I think this issue is more about getting back the synchronous part of the stack trace which is skipped between async methods. And for that we probably need to scan a portion of the stack trace up to the first async caller while running synchronous part of the async function (before the first await), remember that part of the stack trace and insert it between async awaiters when scanning stack trace later. This is somewhat better than scanning the whole stack trace like we did before, and in the common async->async case that scan would end immediately after inspecting the caller.

[mkustermann]

Our stack trace only scans asynchronous awaiters after reaching the first async. All synchronous calls are omitted from the stack trace after the first async (they are technically already gone at that point).

Correct. The difference can be explained more easily as a semantic difference:

• stacktrace shows frames where futures got created (old behavior)
• stacktrace shows frames where futures will be awaited/used (new behavior)
  Opinions differ which is better (we have received feedback from some customers that they do prefer the new behavior over old behavior - since it tells where the value returned from a function will actually be used).

The main usability problem is when there's a truncated stack, which could be solved by handling unawaited specially. This is also the option that would seem to cause the least performance degredation - so I'd say doing anything more expensive would require very strong arguments why it's needed.

[fzyzcjy]

Hi, is there any updates? One awesome feature of Dart is its async/await, and it is used so frequently everywhere in the Dart/Flutter ecosystem. Therefore, it would be great to have this stack trace supported.

[mraleph]

Hi, is there any updates?

We don't currently have any plans to add the "missing" part of the stack trace - this requires capturing stack traces eagerly on entry to async functions when they are not called from other async functions. Our current thinking is that the cost of doing that is going to be prohibitive.

We might try this at some point with a special optimised version of the stack trace capturing code (one that does not need to go into runtime), but right now we have no immediate plans to do that. This might fit into the experiment for sharing stacks for activations of async functions because we might do it by changing calling conventions of the async function to recognise this situation.

[fzyzcjy]

Thanks for the reply and looking forward for the possible future!

[bvoq]

Couldn't this be added with some sort of flag that enables capturing the entire stack?