Ensure that frameTimeNanos passed to VsyncWaiterAndroid is not greater than System.nanoTime

[ColdPaleLight]

The following assertion will cause abort when running Flutter App with an unoptimized local engine.

engine/shell/common/vsync_waiter.cc

Line 100 in edf8fc8

FML_DCHECK(fml::TimePoint::Now() >= frame_start_time);

This patch will fix it.
Related PR: #28817

Pre-launch Checklist

• I read the [Contributor Guide] and followed the process outlined there for submitting PRs.
• I read the [Tree Hygiene] wiki page, which explains my responsibilities.
• I read and followed the [Flutter Style Guide] and the [C++, Objective-C, Java style guides].
• I listed at least one issue that this PR fixes in the description above.
• I added new tests to check the change I am making or feature I am adding, or Hixie said the PR is test-exempt. See [testing the engine] for instructions on
  writing and running engine tests.
• I updated/added relevant documentation (doc comments with ///).
• I signed the [CLA].
• All existing and new tests are passing.

[flutter-dashboard]

It looks like this pull request may not have tests. Please make sure to add tests before merging. If you need an exemption to this rule, contact Hixie on the #hackers channel in Chat.

If you are not sure if you need tests, consider this rule of thumb: the purpose of a test is to make sure someone doesn't accidentally revert the fix. Ask yourself, is there anything in your PR that you feel it is important we not accidentally revert back to how it was before your fix?

Reviewers: Read the Tree Hygiene page and make sure this patch meets those guidelines before LGTMing.

[jason-simmons]

On Android the frame_start_time timestamp is the value passed to the Choreographer.doFrame callback in the Java VsyncWaiter. That timestamp is apparently based on Android's System.nanoTime/System.uptimeMillis (see https://developer.android.com/reference/android/view/Choreographer.FrameCallback)

The assert is comparing it against fml::TimePoint::Now, which is based on DartTimelineTicksSinceEpoch.

@iskakaushik @chinmaygarde Would it make sense to do something like what VsyncWaiterIOS is doing here?
https://github.com/flutter/engine/blob/master/shell/platform/darwin/ios/framework/Source/vsync_waiter_ios.mm#L77

VsyncWaiterAndroid could take the delta between System.nanoTime and the Choreographer.doFrame timestamp and apply that to fml::TimePoint::Now to calculate the frame_start_time

[iskakaushik]

@jason-simmons that sounds like a solid approach. @ColdPaleLight would you be able to make the suggested change to this PR?

[ColdPaleLight]

Hi, @jason-simmons @iskakaushik
The following is the result of my investigation

Unlike iOS, Choreographer.doFrame timestamp may be a value greater than the current time. It may represent a time in the future

For example, in the following example code, RunTimeException will be thrown

@Override
public void doFrame(long frameTimeNanos) {
  long refreshPeriodNanos = (long) (1000000000.0 / fps);
  long delta = System.nanoTime() - frameTimeNanos;
  if (delta < 0) {
      throw new RuntimeException("Delta is" + delta);
  }
  FlutterJNI.nativeOnVsync(
      frameTimeNanos, frameTimeNanos + refreshPeriodNanos, cookie);
}

Choreographer.doFrame timestamp is provided by the Android system rather than the Android application.

Related code:
https://android.googlesource.com/platform/frameworks/base/+/master/core/java/android/view/Choreographer.java#1022

[jason-simmons]

What device and version of Android are you using when you see a negative delta in the code above?

On the devices I tried, the frameTimeNanos passed to the VsyncWaiter doFrame callback is consistently less than the System.nanoTime seen within the callback.

The Android Choreographer sources look like they are trying to ensure that the vsync time is in the past (see https://android.googlesource.com/platform/frameworks/base/+/master/core/java/android/view/Choreographer.java#998, which checks whether the driver provided timestamp is in the future and if so replaces it with the current System.nanoTime)

If some device is calling doFrame with a timestamp that is greater than System.nanoTime, then it might be reasonable to use a zero delta when adjusting the engine's frameStartTime.

[ColdPaleLight]

What device and version of Android are you using when you see a negative delta in the code above?

Huawei P40 Pro with Harmony OS
ELS AN00 (mobile) • UQG5T20413009690 • android-arm64 • Android 10 (API 29)

[ColdPaleLight]

Error Log

[   +3 ms] Updating assets
Debug service listening on ws://127.0.0.1:51481/5ZQLBovCfq8=/ws
Syncing files to device ELS AN00...
[ +149 ms] <- reset
[        ] Compiling dart to kernel with 0 updated files
[   +3 ms] <- recompile package:multiple_flutters/main.dart 85542fbb-b3b3-46fc-80a5-f313c8704046
[        ] <- 85542fbb-b3b3-46fc-80a5-f313c8704046
[  +84 ms] Updating files.
[        ] DevFS: Sync finished
[   +1 ms] Synced 0.0MB.
[   +2 ms] <- accept
[   +4 ms] Connected to _flutterView/0xc0cc3a10.
[  +65 ms] F/flutter (30333): [FATAL:flutter/shell/common/vsync_waiter.cc(100)] Check failed: fml::TimePoint::Now() >= frame_start_time. 
[   +4 ms] F/libc    (30333): Fatal signal 6 (SIGABRT), code -1 (SI_QUEUE) in tid 30333 (ultipleflutters), pid 30333 (ultipleflutters)
[  +56 ms] *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
[        ] Build fingerprint: 'HUAWEI/ELS-AN00/HWELS:10/HUAWEIELS-AN00/102.0.0.168C00:user/release-keys'
[        ] Revision: '0'
[        ] ABI: 'arm'
[        ] SYSVMTYPE: Maple
[        ] APPVMTYPE: Art
[        ] Timestamp: 2021-10-09 06:27:47+0800
[        ] pid: 30333, tid: 30333, name: ultipleflutters  >>> dev.flutter.multipleflutters <<<
[        ] uid: 10042
[        ] signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
[        ] Abort message: '[FATAL:flutter/shell/common/vsync_waiter.cc(100)] Check failed: fml::TimePoint::Now() >= frame_start_time. 

[ColdPaleLight]

If some device is calling doFrame with a timestamp that is greater than System.nanoTime, then it might be reasonable to use a zero delta when adjusting the engine's frameStartTime.

That sounds reasonable.

@jason-simmons @iskakaushik
I made some changes to this PR. Would you mind reviewing it again?

[jason-simmons]

I did another implementation that tries to match how VsyncWaiterIOS calculates the frame start time:
#29093

[ColdPaleLight]

Close this PR and wait for #29093 to land