Exception in flutter microbenchmarks

[floitschG]

When running Flutter's microbenchmarks the error below (at the end of the bug-report) is printed on the console.
Due to timing issues, this error is handled differently with sync-async and makes the benchmark go red.
I'm adding a work-around to the benchmark, but that just treats the symptom.

I have debugged this. Here are my findings:

• lib/stocks/layout_bench.dart runs the following statements in a loop:

      Timer.run(() { ui.window.onBeginFrame(new Duration(milliseconds: iterations * 16)); });
      Timer.run(() { ui.window.onDrawFrame(); });

• The onDrawFrame depends on onBeginFrame to set _doDrawThisFrame to true or false.
• Normally these functions are only called from the loop, but from time to time they are also called from the framework. This can be seen by observing the stacktraces.

This stacktrace is printed when called from the loop (line numbers might be off because of debug lines).

[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #0      LiveTestWidgetsFlutterBinding.handleBeginFrame (package:flutter_test/src/binding.dart:1011)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #1      _TestWidgetsFlutterBinding&BindingBase&SchedulerBinding._handleBeginFrame (package:flutter/src/scheduler/binding.dart:834)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #2      main.<anonymous closure>.<anonymous closure> (file:///usr/local/google/home/floitsch/code/flutter/flutter/dev/benchmarks/microbenchmarks/lib/stocks/layout_bench.dart:65)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #3      _rootRun (dart:async/zone.dart:1122)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #4      _CustomZone.run (dart:async/zone.dart:1023)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #5      _CustomZone.runGuarded (dart:async/zone.dart:925)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #6      _CustomZone.bindCallbackGuarded.<anonymous closure> (dart:async/zone.dart:965)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #7      _rootRun (dart:async/zone.dart:1126)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #8      _CustomZone.run (dart:async/zone.dart:1023)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #9      _CustomZone.bindCallback.<anonymous closure> (dart:async/zone.dart:949)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #10     Timer._createTimer.<anonymous closure> (dart:async/runtime/libtimer_patch.dart:21)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #11     _Timer._runTimers (dart:isolate/runtime/libtimer_impl.dart:382)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #12     _Timer._handleMessage (d

This stacktrace is the one from the framework (line numbers might be off because of debug lines):

[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #0      LiveTestWidgetsFlutterBinding.handleBeginFrame (package:flutter_test/src/binding.dart:1004)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #1      _TestWidgetsFlutterBinding&BindingBase&SchedulerBinding._handleBeginFrame (package:flutter/src/scheduler/binding.dart:834)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #2      _invoke1 (dart:ui/hooks.dart:134)
[microbenchmarks] [STDOUT] [        ] I/flutter (21815): #3      _beginFrame (dart:ui/hooks.dart:105)

For some reason the framework sometimes invokes handleBeginFrame and doDrawFrame. However, if these calls happen in the middle of the two Timer.run, then the second Timer.run call will have an exception.

Here is the exception that is thrown and printed on the console.
The following command was used: dart bin/run.dart -t microbenchmarks

[microbenchmarks] [STDOUT] [+1554 ms] I/flutter ( 3592): ══╡ EXCEPTION CAUGHT BY FLUTTER TEST FRAMEWORK ╞════════════════════════════════════════════════════
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): The following assertion was thrown running a test (but after the test had completed):
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): Failed assertion: boolean expression must not be null
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): 
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): Either the assertion indicates an error in the framework itself, or we should provide substantially
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): more information in this error message to help you determine and fix the underlying cause.
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): In either case, please report this assertion by filing a bug on GitHub:
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592):   https://github.com/flutter/flutter/issues/new
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): 
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): When the exception was thrown, this was the stack:
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #0      LiveTestWidgetsFlutterBinding.handleDrawFrame (package:flutter_test/src/binding.dart:0)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #1      _TestWidgetsFlutterBinding&BindingBase&SchedulerBinding._handleDrawFrame (package:flutter/src/scheduler/binding.dart:842)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #2      main.<anonymous closure>.<anonymous closure> (file:///usr/local/google/home/floitsch/code/flutter/flutter/dev/benchmarks/microbenchmarks/lib/stocks/layout_bench.dart:51)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #11     _Timer._runTimers (dart:isolate/runtime/libtimer_impl.dart:382)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #12     _Timer._handleMessage (dart:isolate/runtime/libtimer_impl.dart:416)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): #13     _RawReceivePortImpl._handleMessage (dart:isolate/runtime/libisolate_patch.dart:165)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): (elided 8 frames from package dart:async)
[microbenchmarks] [STDOUT] [        ] I/flutter ( 3592): ══════════════════════════════════════════════════════════════════════════════════════════════════

[Hixie]

Answering questions from e-mail:

• What triggers the calls from the framework (from lib/ui/window/window.cc:253 - Window::BeginFrame

I assume you mean from the engine. The calls are scheduled when window.scheduleFrame() is called, and they are actually called when the engine decides that it's time to draw a frame (e.g. in response to an OS vsync signal).

• What was supposed to stop these calls?

Nothing stops them.

• What are possible avenues to explore why these calls are still happening.

I imagine these calls are happening because the engine decides it's time to render a frame.

Previously, it seems that scheduling two timers back to back would always end up scheduling these frames into back-to-back tasks with no chance of the engine doing its stuff in between (either that, or this test is slightly flaky, maybe?).

In any case, it looks like it should be pretty straight-forward to adjust this test so that we set window.onBeginFrame and window.onDrawFrame to null before the while loop, and then instead of calling them, we call binding.handleBeginFrame and binding.handleDrawFrame directly.

[floitschG]

Previously, it seems that scheduling two timers back to back would always end up scheduling these frames into back-to-back tasks with no chance of the engine doing its stuff in between (either that, or this test is slightly flaky, maybe?).

No. We had these exceptions already. They were just ignored by the testing framework (I'm guessing because they were delayed enough).

[Hixie]

Ah, interesting.

[github-actions]

This thread has been automatically locked since there has not been any recent activity after it was closed. If you are still experiencing a similar issue, please open a new bug, including the output of flutter doctor -v and a minimal reproduction of the issue.