Skip to content

Shortened stack trace from VM #44169

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
jensjoha opened this issue Nov 12, 2020 · 9 comments
Closed

Shortened stack trace from VM #44169

jensjoha opened this issue Nov 12, 2020 · 9 comments
Assignees
Labels
area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends.

Comments

@jensjoha
Copy link
Contributor

jensjoha commented Nov 12, 2020

With CL https://dart-review.googlesource.com/c/sdk/+/168485/9 (on top of what it's on top of, i.e. 42ac762) it crashes when loading the dill file (obviously it shouldn't, I'll look into that separately) if you run for instance out/ReleaseX64/dart pkg/front_end/test/constant_evaluator_benchmark.dart --platform=out/ReleaseX64/dart-sdk/lib/_internal/dart2js_platform.dill pkg/compiler/bin/dart2js.dart --target=dart2js --nnbd like this:

Unhandled exception:
type 'NullType' is not a subtype of type 'InterfaceType'
#0      BinaryBuilderWithMetadata.readSupertype (package:kernel/binary/ast_from_binary.dart:2632:19)
#1      BinaryBuilder._fillNonTreeNodeList (package:kernel/binary/ast_from_binary.dart:444:32)
#2      BinaryBuilder.readClass (package:kernel/binary/ast_from_binary.dart:1175:5)
#3      BinaryBuilderWithMetadata.readClass (package:kernel/binary/ast_from_binary.dart:2505:32)
#4      BinaryBuilder.readLibrary.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:1016:14)
#5      BinaryBuilder._fillTreeNodeList (package:kernel/binary/ast_from_binary.dart:435:36)
#6      BinaryBuilder._mergeNamedNodeList (package:kernel/binary/ast_from_binary.dart:460:5)
#7      BinaryBuilder.readLibrary (package:kernel/binary/ast_from_binary.dart:1014:5)
#8      BinaryBuilderWithMetadata.readLibrary (package:kernel/binary/ast_from_binary.dart:2491:34)
#9      BinaryBuilder._readOneComponent (package:kernel/binary/ast_from_binary.dart:792:25)
#10     BinaryBuilder.readComponent.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:549:33)
#11     Timeline.timeSync (dart:developer/timeline.dart:163:22)
#12     BinaryBuilder.readComponent (package:kernel/binary/ast_from_binary.dart:519:21)
#13     IncrementalCompiler.prepareSummary (package:front_end/src/fasta/incremental_compiler.dart:1589:12)
#14     IncrementalCompiler.ensurePlatformAndInitialize (package:front_end/src/fasta/incremental_compiler.dart:1125:23)
<asynchronous suspension>
#15     IncrementalCompiler.computeDelta.<anonymous closure> (package:front_end/src/fasta/incremental_compiler.dart:227:11)
<asynchronous suspension>
<asynchronous suspension>

which is missing something at the end... e.g. which line in constant_evaluator_benchmark.dart actually came to this path?

If I add --no-lazy-async-stacks --causal-async-stacks I instead get

Unhandled exception:
type 'NullType' is not a subtype of type 'InterfaceType'
#0      BinaryBuilderWithMetadata.readSupertype (package:kernel/binary/ast_from_binary.dart:2632:19)
#1      BinaryBuilder._fillNonTreeNodeList (package:kernel/binary/ast_from_binary.dart:444:32)
#2      BinaryBuilder.readClass (package:kernel/binary/ast_from_binary.dart:1175:5)
#3      BinaryBuilderWithMetadata.readClass (package:kernel/binary/ast_from_binary.dart:2505:32)
#4      BinaryBuilder.readLibrary.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:1016:14)
#5      BinaryBuilder._fillTreeNodeList (package:kernel/binary/ast_from_binary.dart:435:36)
#6      BinaryBuilder._mergeNamedNodeList (package:kernel/binary/ast_from_binary.dart:460:5)
#7      BinaryBuilder.readLibrary (package:kernel/binary/ast_from_binary.dart:1014:5)
#8      BinaryBuilderWithMetadata.readLibrary (package:kernel/binary/ast_from_binary.dart:2491:34)
#9      BinaryBuilder._readOneComponent (package:kernel/binary/ast_from_binary.dart:792:25)
#10     BinaryBuilder.readComponent.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:549:33)
#11     Timeline.timeSync (dart:developer/timeline.dart:163:22)
#12     BinaryBuilder.readComponent (package:kernel/binary/ast_from_binary.dart:519:21)
#13     IncrementalCompiler.prepareSummary (package:front_end/src/fasta/incremental_compiler.dart:1589:12)
#14     IncrementalCompiler.ensurePlatformAndInitialize (package:front_end/src/fasta/incremental_compiler.dart:1125:23)
<asynchronous suspension>
#15     IncrementalCompiler.computeDelta.<anonymous closure> (package:front_end/src/fasta/incremental_compiler.dart:227:17)
<asynchronous suspension>
#16     IncrementalCompiler.computeDelta.<anonymous closure> (package:front_end/src/fasta/incremental_compiler.dart)
#17     CompilerContext.runInContext.<anonymous closure>.<anonymous closure> (package:front_end/src/fasta/compiler_context.dart:124:46)
#18     new Future.sync (dart:async/future.dart:223:31)
#19     CompilerContext.runInContext.<anonymous closure> (package:front_end/src/fasta/compiler_context.dart:124:19)
#20     _rootRun (dart:async/zone.dart:1186:13)
#21     _CustomZone.run (dart:async/zone.dart:1090:19)
#22     _runZoned (dart:async/zone.dart:1626:10)
#23     runZoned (dart:async/zone.dart:1546:10)
#24     CompilerContext.runInContext (package:front_end/src/fasta/compiler_context.dart:123:12)
#25     IncrementalCompiler.computeDelta (package:front_end/src/fasta/incremental_compiler.dart:218:20)
#26     main ([...]/pkg/front_end/test/constant_evaluator_benchmark.dart:169:29)
#27     _startIsolate.<anonymous closure> (dart:isolate-patch/isolate_patch.dart:315:32)
#28     _RawReceivePortImpl._handleMessage (dart:isolate-patch/isolate_patch.dart:184:12)

which gives me my answer, so I assume the shortened stacktrace is a bug with the lazy async stuff.

/cc @cskau-g

@ghost ghost self-assigned this Nov 12, 2020
@mkustermann mkustermann added the area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends. label Nov 12, 2020
@ghost
Copy link

ghost commented Nov 17, 2020

I've tried reproducing this, but patching 168485 onto 95e4e03 has given me no exceptions in the hour or so I've let it run now. (It appears to be an infinite loop?)

@jensjoha, do you have a reproducing example I can try, or has something changed in the meantime?

As for the issue described, it is suspicious that you're seeing two gaps at the end of the trace, though I don't currently have a good guess how that could happen.

@jensjoha
Copy link
Contributor Author

Yeah, the underlying bug was fixed, that's why I noted it should be on top of 42ac762 --- checking out patchset #9 (git fetch https://dart.googlesource.com/sdk refs/changes/85/168485/9 && git checkout -b change-168485 FETCH_HEAD) should do the trick though (I'm currently verifying that).

@jensjoha
Copy link
Contributor Author

And yes, it's an infinite loop, but it crashes up front (when it crashes). The above is verified (on my machine at least):

$ time out/ReleaseX64/dart pkg/front_end/test/constant_evaluator_benchmark.dart --platform=out/ReleaseX64/dart-sdk/lib/_internal/dart2js_platform.dill pkg/compiler/bin/dart2js.dart --target=dart2js --nnbd
Unhandled exception:
type 'NullType' is not a subtype of type 'InterfaceType'
#0      BinaryBuilderWithMetadata.readSupertype (package:kernel/binary/ast_from_binary.dart:2632:19)
#1      BinaryBuilder._fillNonTreeNodeList (package:kernel/binary/ast_from_binary.dart:444:32)
#2      BinaryBuilder.readClass (package:kernel/binary/ast_from_binary.dart:1175:5)
#3      BinaryBuilderWithMetadata.readClass (package:kernel/binary/ast_from_binary.dart:2505:32)
#4      BinaryBuilder.readLibrary.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:1016:14)
#5      BinaryBuilder._fillTreeNodeList (package:kernel/binary/ast_from_binary.dart:435:36)
#6      BinaryBuilder._mergeNamedNodeList (package:kernel/binary/ast_from_binary.dart:460:5)
#7      BinaryBuilder.readLibrary (package:kernel/binary/ast_from_binary.dart:1014:5)
#8      BinaryBuilderWithMetadata.readLibrary (package:kernel/binary/ast_from_binary.dart:2491:34)
#9      BinaryBuilder._readOneComponent (package:kernel/binary/ast_from_binary.dart:792:25)
#10     BinaryBuilder.readComponent.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:549:33)
#11     Timeline.timeSync (dart:developer/timeline.dart:163:22)
#12     BinaryBuilder.readComponent (package:kernel/binary/ast_from_binary.dart:519:21)
#13     IncrementalCompiler.prepareSummary (package:front_end/src/fasta/incremental_compiler.dart:1589:12)
#14     IncrementalCompiler.ensurePlatformAndInitialize (package:front_end/src/fasta/incremental_compiler.dart:1125:23)
<asynchronous suspension>
#15     IncrementalCompiler.computeDelta.<anonymous closure> (package:front_end/src/fasta/incremental_compiler.dart:227:11)
<asynchronous suspension>
<asynchronous suspension>

real    0m3.642s
user    0m5.143s
sys     0m0.708s

@ghost
Copy link

ghost commented Nov 17, 2020

Gotcha. I'll give that a try. Thanks, Jens!

@ghost
Copy link

ghost commented Nov 17, 2020

I've narrowed it down to:

() => new Future<T>.sync(() => action(this)).whenComplete(clear),

Which I've boiled down to this:

void clear() => 'Does nothing';

myAction() async {
  await 0;
  throw 'async throw from myAction.';
}

// `myaction` is run immediately in Future.sync, eventually throws, which is then
// being passed on to the internals of whenComplete, which runs `clear` and
// rethrows from there.
doThings() async => Future.sync(() => myAction()).whenComplete(clear);

main() async => await doThings();

So when we try do the stack unwinding we have:

  1. myAction.
  2. async gap, since myAction is async.
  3. (the internals of clear, which happens to be invisible.)
  4. async gap, since the above is also async.

And from there we run out of chain to lazily unwind, hence the short stack with --lazy-async-stack.
Also note the two async gaps at the end, due to part of the trace being marked invisible.

@mkustermann, do you see anything we can do about this?

@mkustermann
Copy link
Member

mkustermann commented Nov 18, 2020

@jensjoha The code in the frontend uses .whenComplete() which is a very old mechanism (similar to .then(), .catchError()) that was useful before we had async/await. If code is written in async/await style the stack traces work as expected. Could you use the following more readable form:

diff --git a/pkg/front_end/lib/src/fasta/compiler_context.dart b/pkg/front_end/lib/src/fasta/compiler_context.dart
index e64cd29900e..fffd1ac7817 100644
--- a/pkg/front_end/lib/src/fasta/compiler_context.dart
+++ b/pkg/front_end/lib/src/fasta/compiler_context.dart
@@ -120,9 +120,13 @@ class CompilerContext {
   /// Perform [action] in a [Zone] where [this] will be available as
   /// `CompilerContext.current`.
   Future<T> runInContext<T>(Future<T> action(CompilerContext c)) {
-    return runZoned(
-        () => new Future<T>.sync(() => action(this)).whenComplete(clear),
-        zoneValues: {compilerContextKey: this});
+    return runZoned(() async {
+      try {
+        await action(this);
+      } finally {
+        clear();
+      }
+    }, zoneValues: {compilerContextKey: this});
   }

in the frontend package?

@cskau-g One action item we should definitely take here is that we should avoid emitting consecutive <async gap> markers - if we filter an invisible frame we should also filter the corresponding async gap marker (if there is one).

We could consider writing _Future.whenComplete() implementation using this async/await style. Though we would need to check if a) core library team would be ok with _Future implementation using async/await syntax b) whether there are performance/code size implications for VM or dart2js.

Alternatively we could make VM use _FutureListener.result for unwinding (depending on _FutureListener.state) if the callback isn't an async function.

dart-bot pushed a commit that referenced this issue Nov 19, 2020
TEST=tools/test.py -n dartk-linux-release-x64 vm/dart_2/causal_stacks

Bug: #44169
Change-Id: I27dbe298ea30ef562984788223080fcb65f43da4
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/172961
Reviewed-by: Tess Strickland <[email protected]>
Commit-Queue: Clement Skau <[email protected]>
@ghost
Copy link

ghost commented Nov 19, 2020

@cskau-g One action item we should definitely take here is that we should avoid emitting consecutive <async gap> markers - if we filter an invisible frame we should also filter the corresponding async gap marker (if there is one).

Done: https://dart-review.googlesource.com/c/sdk/+/172961

Alternatively we could make VM use _FutureListener.result for unwinding (depending on _FutureListener.state) if the callback isn't an async function.

I will follow up on this.

dart-bot pushed a commit that referenced this issue Nov 23, 2020
TEST=tools/test.py -n dartk-linux-release-x64 vm/dart_2/causal_stacks

Bug: #44169
Change-Id: Ia5810ca3585f8e90b6fb91827a892a038e82f13b
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/173264
Commit-Queue: Clement Skau <[email protected]>
Reviewed-by: Martin Kustermann <[email protected]>
@ghost
Copy link

ghost commented Nov 23, 2020

Alternatively we could make VM use _FutureListener.result for unwinding (depending on _FutureListener.state) if the callback isn't an async function.

Done: https://dart-review.googlesource.com/c/sdk/+/173264

That should address all the VM concerns for this issue.

I'll reassign to you, @jensjoha, to decide if you folks want to follow up on Martin's suggestion in #44169 (comment).
Otherwise I think we can close this issue.

@ghost ghost assigned jensjoha and unassigned ghost Nov 23, 2020
@jensjoha
Copy link
Contributor Author

Reintroducing the crash I now get

type 'NullType' is not a subtype of type 'InterfaceType'
#0      BinaryBuilderWithMetadata.readSupertype (package:kernel/binary/ast_from_binary.dart:2634:19)
#1      BinaryBuilder._fillNonTreeNodeList (package:kernel/binary/ast_from_binary.dart:444:32)
#2      BinaryBuilder.readClass (package:kernel/binary/ast_from_binary.dart:1177:5)
#3      BinaryBuilderWithMetadata.readClass (package:kernel/binary/ast_from_binary.dart:2507:32)
#4      BinaryBuilder.readLibrary.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:1016:14)
#5      BinaryBuilder._fillTreeNodeList (package:kernel/binary/ast_from_binary.dart:435:36)
#6      BinaryBuilder._mergeNamedNodeList (package:kernel/binary/ast_from_binary.dart:460:5)
#7      BinaryBuilder.readLibrary (package:kernel/binary/ast_from_binary.dart:1014:5)
#8      BinaryBuilderWithMetadata.readLibrary (package:kernel/binary/ast_from_binary.dart:2493:34)
#9      BinaryBuilder._readOneComponent (package:kernel/binary/ast_from_binary.dart:792:25)
#10     BinaryBuilder.readComponent.<anonymous closure> (package:kernel/binary/ast_from_binary.dart:549:33)
#11     Timeline.timeSync (dart:developer/timeline.dart:163:22)
#12     BinaryBuilder.readComponent (package:kernel/binary/ast_from_binary.dart:519:21)
#13     IncrementalCompiler.prepareSummary (package:front_end/src/fasta/incremental_compiler.dart:1589:12)
#14     IncrementalCompiler.ensurePlatformAndInitialize (package:front_end/src/fasta/incremental_compiler.dart:1125:23)
<asynchronous suspension>
#15     IncrementalCompiler.computeDelta.<anonymous closure> (package:front_end/src/fasta/incremental_compiler.dart:227:11)
<asynchronous suspension>
#16     main ([...]/pkg/front_end/test/constant_evaluator_benchmark.dart:191:3)

which seems fine =)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-vm Use area-vm for VM related issues, including code coverage, and the AOT and JIT backends.
Projects
None yet
Development

No branches or pull requests

2 participants