Dropped Frames with Half Frame Rate on Android

[Neil Kronlage]

Hi, 

I work on Meta Quest Browser - a fork of Chromium for Android.

I'm looking at doing something similar to Chromium on Window's run_at_half_refresh_rate_ logic to try to reduce the CPU use of our browser in certain scenarios: https://source.chromium.org/chromium/chromium/src/+/main:components/viz/service/frame_sinks/external_begin_frame_source_win.cc;l=62;drc=1bf071a86da81bce421efad0a746aabb371888cb

and things look pretty good except I'm seeing a high percent (~2%) of dropped frames when playing videos.

This is also reproducible on a stock Chromium build running at half frame rate on a Samsung Galaxy S22.

Here's a simplified version of what I've applied:

diff --git a/components/viz/service/frame_sinks/external_begin_frame_source_android.cc b/components/viz/service/frame_sinks/external_begin_frame_source_android.cc
index 349e0b7c102d8..196dc3f920f24 100644
--- a/components/viz/service/frame_sinks/external_begin_frame_source_android.cc
+++ b/components/viz/service/frame_sinks/external_begin_frame_source_android.cc
@@ -266,6 +266,17 @@ void ExternalBeginFrameSourceAndroid::OnVSyncImpl(
   base::TimeTicks frame_time = ToTimeTicks(time_nanos);
   base::TimeTicks deadline = ToTimeTicks(deadline_nanos);
 
+  if (skip_next_vsync_) {
+    TRACE_EVENT_INSTANT0("gpu",
+                         "ExternalBeginFrameSourceAndroid::OnVSync - skip_vsync",
+                         TRACE_EVENT_SCOPE_THREAD);
+    skip_next_vsync_ = false;
+    return;
+  }
+
+  skip_next_vsync_ = true;
+  vsync_period *= 2;
+
   auto begin_frame_args = begin_frame_args_generator_.GenerateBeginFrameArgs(
       source_id(), frame_time, deadline, vsync_period);
   if (features::IsAndroidFrameDeadlineEnabled()) {
diff --git a/components/viz/service/frame_sinks/external_begin_frame_source_android.h b/components/viz/service/frame_sinks/external_begin_frame_source_android.h
index c3ce7f18d0e5c..e74f73c05fcbd 100644
--- a/components/viz/service/frame_sinks/external_begin_frame_source_android.h
+++ b/components/viz/service/frame_sinks/external_begin_frame_source_android.h
@@ -61,6 +61,8 @@ class VIZ_SERVICE_EXPORT ExternalBeginFrameSourceAndroid
   std::unique_ptr<AChoreographerImpl> achoreographer_;
   base::android::ScopedJavaGlobalRef<jobject> j_object_;
   BeginFrameArgsGenerator begin_frame_args_generator_;
+
+  bool skip_next_vsync_ = false;
 };
 
 }  // namespace viz

When I apply these changes and run on the Galaxy S22 phone, I see testufo.com showing 30 fps as expected. But going to a test page I made (https://d5jgqkvdbh4xp.cloudfront.net/video.html) and selecting the 30 fps video, I see a 2-3% dropped frame count - much higher than a 60 fps video running at full frame rate ( < 0.5%).

I've spent some time trying to understand the dropped frames in Perfetto, but am pretty lost so hoping for some pointers on what could be causing this. Any help or ideas would be appreciated. I can also try to share Perfetto traces if that helps - lmk what categories would help.

Thanks for any insights!

-Neil

[Dale Curtis]

Since this isn't a hardware vsync change, skipping vsyncs like this may exacerbate timing errors. If the algorithm is truly running at 30Hz for a 60fps video, you should be able to enable the logging in VideoRendererAlgorithm and VideoCadenceEstimator and see it clamp to a [1:0] cadence.

- dale

--
You received this message because you are subscribed to the Google Groups "media-dev" group.
To unsubscribe from this group and stop receiving emails from it, send an email to media-dev+...@chromium.org.
To view this discussion on the web visit https://groups.google.com/a/chromium.org/d/msgid/media-dev/28affbcc-0f80-4339-91cd-f6335128fc74n%40chromium.org.

[Dale Curtis]

(from the right e-mail this time)

The cadence you want in this case is "[1:0]" not "[1]":

https://source.chromium.org/chromium/chromium/src/+/main:media/filters/video_cadence_estimator_unittest.cc;l=148;drc=d5626e7d94666d8bfde13f5a4fbc097f3b87d093

If it's [1] it sounds like VRA is still being told to emit 60Hz worth of frames.

- dale

On Wed, Jul 10, 2024 at 3:47 PM Neil Kronlage <neil.k...@gmail.com> wrote:

Thanks Dale! I've confirmed the cadence is [1] and I see the code is trying to pick up one video frame per VSync so it appears something else is going on.

Digging in further, I've found that updating the in-page frame dropped counter element is contributing a lot to the dropped frames. Disabling that improves things for my sample, but we can't rely on all web pages not touching the DOM during video playback so I'd still like to figure this out.

I've been trying to understand what's going on here but I'm getting really lost in the weeds so would love any additional help/pointers with this.

What I'm seeing is that when the frame counter updates, there is a AsyncLayerTreeFrameSink::SubmitCompositorFrame call.

After the next VSync, I see DisplayDamageTracker::RunDrawCallbacks running SendAckToClient on a different viz::Surface than it was in the previous VSyncs that were not dropping frames:

https://source.chromium.org/chromium/chromium/src/+/main:components/viz/service/display/display_damage_tracker.cc;l=265

It appears this eventually causes VideoFrameSubmitter::SubmitFrame call return to false because waiting_for_compositor_ack_ is true since it didn't get the ack it was previously getting:

https://source.chromium.org/chromium/chromium/src/+/main:third_party/blink/renderer/platform/graphics/video_frame_submitter.cc;l=747

so PutCurrentFrame() is not getting called and the frame gets dropped:

https://source.chromium.org/chromium/chromium/src/+/main:third_party/blink/renderer/platform/graphics/video_frame_submitter.cc;l=828

Any tips on what else to look at here, or if there are any logs/traces I could share that would help pinpoint the issue?

[Neil Kronlage]

In this case, I'm running a 30 fps video on a 30 hz display (60 hz phone but skipping every other VSync). Should it still be "[1:0]" ?

The test fails with "[1:0]" but passes if I use "[1]":

    VerifyCadenceVector(&estimator, 30, 30, "[1]");

[Dale Curtis]

Ah, yes, if it's 30fps in 30Hz it should be [1]. We've talked about making `waiting_for_compositor_ack_` a counter instead of a bool, you might see if allowing more pending ACKs fixes the issue. It will likely increase memory pressure though.

Once things get into Viz I'm not sure what might be happening. +Jonathan Ross and +Frank Liberato  who may have some pointers.

- dale

[Jonathan Ross]

Hey,

Regarding 

"After the next VSync, I see DisplayDamageTracker::RunDrawCallbacks running SendAckToClient on a different viz::Surface than it was in the previous VSyncs that were not dropping frames:"

Was this viz::Surface a different embedded client, or an updated viz::Surface from the VideoFrameSubmitter? 

• viz::SurfaceId has a viz::FrameSinkId for the client, and the viz::LocalSurfaceId has `embed_token`. If those components are changing, then we are dealing with different clients.
• viz::LocalSurfaceId can change when different visual properties need to be updated. You could confirm if VideoFrameSubmitter::SubmitFrame is advancing this id when calling SubmitCompositorFrame

If it is the Former, then some other client was holding up frame production.

Were things running smoothly I would expect a flow of:

1. VideoFrameSubmitter::OnBeginFrame -> SubmitCompositorFrame
2. Display::DrawAndSwap -> DisplayDamageTracker::RunDrawCallbacks
   
3. VideoFrameSubmitter::DidReceiveCompositorFrameAck
4. VideoFrameSubmitter::OnBeginFrame
   

Were Step 2)/3) to occur after 4) then we could be in a bad state.

• VideoFrameSubmitter::DidReceiveCompositorFrameAck doesn't appear to attempt to draw if we have received an OnBeginFrame but done nothing
  
• A 30fps video running on a 60Hz display might not run into this issue, as it could still submit the video frame during the extra VSync.

I would +1 testing changes to  `waiting_for_compositor_ack_`. We've been encountering problems due to the Ack in non video clients as well. I'm considering some alternatives to experiment with in Q4.

- Jon

[Neil Kronlage]

Thanks Dale and Jon! Appreciate all the help here!

> We've talked about making `waiting_for_compositor_ack_` a counter instead of a bool, you might see if allowing more pending ACKs fixes the issue.

It looks like it is already a counter: https://source.chromium.org/chromium/chromium/src/+/main:third_party/blink/renderer/platform/graphics/video_frame_submitter.h;l=163

I've only ever seen it go to up to 1 though so I don't think it's caused by a dropped ack.

> Was this viz::Surface a different embedded client, or an updated viz::Surface from the VideoFrameSubmitter?

Looks like a different client. Typically it's Acking FrameSinkId(3, 2147483648) but in the bad case it Acks FrameSinkId(3, 3). 

> If it is the Former, then some other client was holding up frame production.

Do you have more details on this? Is there any logs that would show that?

> Were Step 2)/3) to occur after 4) then we could be in a bad state.

I've added logs with traces of the flow you described and collected a random one that dropped a frame below.

In Vsync 4, the VideoFrameSubmitter::DidReceiveCompositorFrameAck call happens after DrawAndSwap. In VSync 3, the Ack only went to FrameSinkId(3, 3) before the call to VideoFrameSubmitter::OnBeginFrame so it skipped out on the PutCurrentFrame call at that time.

// VSync 1
07-12 10:06:24.617  7201  7247 E chromium: [ERROR:external_begin_frame_source_android.cc(280)] ExternalBeginFrameSourceAndroid::OnVSyncImpl
07-12 10:06:24.619  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(389)] VideoFrameSubmitter::OnBeginFrame
07-12 10:06:24.619  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(371)] VideoFrameSubmitter::DidReceiveCompositorFrameAck
07-12 10:06:24.625  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(776)] VideoFrameSubmitter::SubmitFrame calling SubmitCompositorFrame
07-12 10:06:24.625  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(115)] VideoFrameSubmitter::FrameSinkBundleProxy::SubmitCompositorFrame
07-12 10:06:24.625  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(503)] VideoFrameSubmitter::OnBeginFrame SubmitFrame Succeeded - calling PutCurrentFrame
07-12 10:06:24.627  7201  7247 E chromium: [ERROR:display.cc(669)] Display::DrawAndSwap
07-12 10:06:24.627  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(268)] DisplayDamageTracker::RunDrawCallbacks processing surfaces_to_ack_on_next_draw_: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))
07-12 10:06:24.628  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(0, 1), LocalSurfaceId(3, 2, 390E607F5C6728B83CE2A2B856C29633))
07-12 10:06:24.628  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.628  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))

// innerHTML set here:
07-12 10:06:24.634  7163  7232 V chromium: [VERBOSE2:html_document_parser_fastpath.cc(1195)] innerHTML fast-path parser failed, 4
07-12 10:06:24.634  7163  7232 V chromium: [VERBOSE1:html_tree_builder.cc(2781)] Not implemented.


// VSync 2
07-12 10:06:24.651  7201  7247 E chromium: [ERROR:external_begin_frame_source_android.cc(280)] ExternalBeginFrameSourceAndroid::OnVSyncImpl
07-12 10:06:24.652  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(389)] VideoFrameSubmitter::OnBeginFrame
07-12 10:06:24.652  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(371)] VideoFrameSubmitter::DidReceiveCompositorFrameAck
07-12 10:06:24.657  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(776)] VideoFrameSubmitter::SubmitFrame calling SubmitCompositorFrame
07-12 10:06:24.657  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(115)] VideoFrameSubmitter::FrameSinkBundleProxy::SubmitCompositorFrame
07-12 10:06:24.657  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(503)] VideoFrameSubmitter::OnBeginFrame SubmitFrame Succeeded - calling PutCurrentFrame
07-12 10:06:24.663  7201  7247 E chromium: [ERROR:display.cc(669)] Display::DrawAndSwap
07-12 10:06:24.666  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(268)] DisplayDamageTracker::RunDrawCallbacks processing surfaces_to_ack_on_next_draw_: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))
07-12 10:06:24.666  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(0, 1), LocalSurfaceId(3, 2, 390E607F5C6728B83CE2A2B856C29633))
07-12 10:06:24.666  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.666  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))


// VSync 3
07-12 10:06:24.684  7201  7247 E chromium: [ERROR:external_begin_frame_source_android.cc(280)] ExternalBeginFrameSourceAndroid::OnVSyncImpl
07-12 10:06:24.686  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(389)] VideoFrameSubmitter::OnBeginFrame
07-12 10:06:24.686  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(371)] VideoFrameSubmitter::DidReceiveCompositorFrameAck
07-12 10:06:24.694  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(776)] VideoFrameSubmitter::SubmitFrame calling SubmitCompositorFrame
07-12 10:06:24.694  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(115)] VideoFrameSubmitter::FrameSinkBundleProxy::SubmitCompositorFrame
07-12 10:06:24.694  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(503)] VideoFrameSubmitter::OnBeginFrame SubmitFrame Succeeded - calling PutCurrentFrame
07-12 10:06:24.695  7201  7247 E chromium: [ERROR:display.cc(669)] Display::DrawAndSwap
07-12 10:06:24.695  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(268)] DisplayDamageTracker::RunDrawCallbacks processing surfaces_to_ack_on_next_draw_: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.695  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(0, 1), LocalSurfaceId(3, 2, 390E607F5C6728B83CE2A2B856C29633))
07-12 10:06:24.695  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.696  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))


// VSync 4
07-12 10:06:24.718  7201  7247 E chromium: [ERROR:external_begin_frame_source_android.cc(280)] ExternalBeginFrameSourceAndroid::OnVSyncImpl
07-12 10:06:24.719  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(389)] VideoFrameSubmitter::OnBeginFrame
07-12 10:06:24.719  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(749)] VideoFrameSubmitter::SubmitFrame returning false because waiting_for_compositor_ack_(1) > 0 && !frame_size_changed
07-12 10:06:24.719  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(494)] VideoFrameSubmitter::OnBeginFrame SubmitFrame Failed - not calling PutCurrentFrame
07-12 10:06:24.719  7201  7247 E chromium: [ERROR:display.cc(669)] Display::DrawAndSwap
07-12 10:06:24.720  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(268)] DisplayDamageTracker::RunDrawCallbacks processing surfaces_to_ack_on_next_draw_: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))
07-12 10:06:24.720  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(0, 1), LocalSurfaceId(3, 2, 390E607F5C6728B83CE2A2B856C29633))
07-12 10:06:24.720  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.720  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))
07-12 10:06:24.721  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(371)] VideoFrameSubmitter::DidReceiveCompositorFrameAck


// VSync 5
07-12 10:06:24.751  7201  7247 E chromium: [ERROR:external_begin_frame_source_android.cc(280)] ExternalBeginFrameSourceAndroid::OnVSyncImpl
07-12 10:06:24.752  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(389)] VideoFrameSubmitter::OnBeginFrame
07-12 10:06:24.752  7163  7285 E chromium: [ERROR:video_renderer_algorithm.cc(293)] VideoRendererAlgorithm::OnLastFrameDropped
07-12 10:06:24.753  7163  7285 V chromium: [VERBOSE2:video_renderer_algorithm.cc(190)] Dropping unrendered (or always dropped) frame 10.9667 s, wall clock: 177288840736 (1, 1)
07-12 10:06:24.753  7163  7285 V chromium: [VERBOSE2:video_renderer_algorithm.cc(209)] Deadline: [177288919044, 177288952377], Interval: 33333, Duration: 33333
07-12 10:06:24.758  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(776)] VideoFrameSubmitter::SubmitFrame calling SubmitCompositorFrame
07-12 10:06:24.758  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(115)] VideoFrameSubmitter::FrameSinkBundleProxy::SubmitCompositorFrame
07-12 10:06:24.758  7163  7285 E chromium: [ERROR:video_frame_submitter.cc(503)] VideoFrameSubmitter::OnBeginFrame SubmitFrame Succeeded - calling PutCurrentFrame
07-12 10:06:24.759  7201  7247 E chromium: [ERROR:display.cc(669)] Display::DrawAndSwap
07-12 10:06:24.760  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(268)] DisplayDamageTracker::RunDrawCallbacks processing surfaces_to_ack_on_next_draw_: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))
07-12 10:06:24.760  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(0, 1), LocalSurfaceId(3, 2, 390E607F5C6728B83CE2A2B856C29633))
07-12 10:06:24.760  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 3), LocalSurfaceId(8, 1, 8429879452800C41C43FD7594DF91109))
07-12 10:06:24.760  7201  7247 E chromium: [ERROR:display_damage_tracker.cc(278)] DisplayDamageTracker::RunDrawCallbacks processing previous_contained_surfaces: SurfaceId(FrameSinkId(3, 2147483648), LocalSurfaceId(1, 1, EC087F01A8EC0E0DA1DCA772E36B623A))

[Neil Kronlage]

I made a little progress to reduce the frame drops to ~0.5%.

Turns out I had only increased the period passed to GenerateBeginFrameArgs, but left the deadline untouched so BeginFrame calls were getting scheduled too early on frames that touched the DOM.

I missed that the Windows version was modifying the deadline based on the doubled interval since the Windows side calculated the deadline at the point of creating the BeginFrameArgs, where Android did it earlier (and did it in multiple places).

I created a change to try to better match how Windows does this and remove the duplication: https://chromium-review.googlesource.com/c/chromium/src/+/5718290

Lmk if that looks like a good change to you.

I'm going to continue to try to track down where the remaining dropped frames come from.

[Jonathan Ross]

Hey,

Thanks for the patch.

>> If it is the Former, then some other client was holding up frame production.

> Do you have more details on this? Is there any logs that would show that?

The viz::DisplayScheduler attempts to wait for all clients subscribed to BeginFrames to submit before performing DrawAndSwap

• This is checked in DisplayScheduler::DesiredBeginFrameDeadlineMode, looking at has_pending_surfaces_
• If we are waiting you wouldn't see the trace "All active surfaces ready". But one of the results further in the method. Likely "More damage expected soon"
• Logic for a viz::Surface being pending is in DisplayDamageTracker::HasPendingSurfaces
• This would show in a trace as "DisplayDamageTracker::HasPendingSurfaces"

There's an interesting order in VSync 3 vs VSync 4 above.

• VSync 3 has OnBeginFrame -> DidReceiveCompositorFrameAck
• VSync 4 has OnBeginFrame -> throttled -> DrawAndSwap -> DidReceiveCompositorFrameAck

I think this implies that the feature OnBeginFrameAcks is enabled in this build?

You call out that VSync3 has a different "surfaces_to_ack_on_next_draw_". Determining why the video source doesn't get include would be a good next step. 

[Neil Kronlage]

I think having the incorrect deadline (it wasn't doubled like the interval was) caused pretty much all of these issues I mentioned initially. I believe what was happening was the processing of the AsyncLayerTree sink caused a ScheduleBeginFrameDeadline to use the incorrect deadline, which caused the early DrawAndSwap before the Video processed the ack.

So the other issue I'm seeing after fixing that is a low but steady dropped frame count that appears to be caused by VSyncs taking slightly longer than the interval to come in. On my Galaxy S22, the interval is 16.666ms but the actual timestamps on Vsyncs are about 16.74ms apart.

You can see this with a frame drop roughly every 7s when watching the 50hz video on this site:  https://d5jgqkvdbh4xp.cloudfront.net/video.html

And there are logs like

07-18 21:08:33.117 31368 31510 V chromium: [VERBOSE2:video_renderer_algorithm.cc(191)] Dropping unrendered (or always dropped) frame 110.26 s, wall clock: 356720798209 (1, 1)

I put together a unit test to try to represent this: https://chromium-review.googlesource.com/c/chromium/src/+/5723092

The test changes the display to run at a slightly slower rate (to mimic the longer times between vsyncs I'm seeing on the phone/Quest) while keeping the interval at 60hz.

The test fails with:

../../media/filters/video_renderer_algorithm_unittest.cc:251: Failure
The difference between GetUsableFrameCount(deadline_max) and EffectiveFramesQueued() is 1, which exceeds fresh_algorithm ? 0 : 1, where
GetUsableFrameCount(deadline_max) evaluates to 3,
EffectiveFramesQueued() evaluates to 2, and
fresh_algorithm ? 0 : 1 evaluates to 0.
Google Test trace:
../../media/filters/video_renderer_algorithm_unittest.cc:181: Rendering 50.000 fps into 59.800
Stack trace:
#0 0x55f26d6c1599 media::VideoRendererAlgorithmTest_SlightlyOffDisplayRate_Test::TestBody() [../../media/filters/video_renderer_algorithm_unittest.cc:241:9]

[  FAILED  ] VideoRendererAlgorithmTest.SlightlyOffDisplayRate (2 ms)
[----------] 1 test from VideoRendererAlgorithmTest (1906 ms total)

[----------] Global test environment tear-down
[==========] 1 test from 1 test suite ran. (1906 ms total)
[  PASSED  ] 0 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] VideoRendererAlgorithmTest.SlightlyOffDisplayRate

 1 FAILED TEST
[1/1] VideoRendererAlgorithmTest.SlightlyOffDisplayRate (2 ms)
1 test failed:
    VideoRendererAlgorithmTest.SlightlyOffDisplayRate (../../media/filters/video_renderer_algorithm_unittest.cc:1694)

 

Do those errors look like it'd explain the dropped frames I'm seeing? Any thoughts on how these slightly longer vsyncs should be handled?

[Jonathan Ross]

Responses inline below

On Fri, Jul 19, 2024 at 12:12 AM Neil Kronlage <neil.k...@gmail.com> wrote:

So the other issue I'm seeing after fixing that is a low but steady dropped frame count that appears to be caused by VSyncs taking slightly longer than the interval to come in. On my Galaxy S22, the interval is 16.666ms but the actual timestamps on Vsyncs are about 16.74ms apart.

Just want to confirm. Were you seeing viz::BeginFrameArgs::frame_time that had the deltas of 16.74ms. Or was this arrival/processing time within the video code that had such deltas? 

It does appear that we have a 5% tolerance for shifts in the frame_time. Checked in BeginFrameSource::BeginFrameArgsGenerator::EstimateTickCountsBetween. However there is no adjustment to the deadline when this occurs. You did unify the deadline calculation in ExternalBeginFrameSourceAndroid::OnVSyncImpl. We could question the reliability of `jlong period_micros` on Android when there is such drift.

I'm less familiar with the underlying work in media/filters/video_renderer_algorithm_unittest.cc that uses the frame times/deadlines. Hopefully someone on media can provide their thoughts.

[Dale Curtis]

I'll look at the algorithm test a bit more closely, it's been a long time since I wrote that.

I'm not surprised to see occasional frame drops though, the algorithm tries to favor visual smoothness until an a/v sync tolerance is exceeded. In this case it should be stretching the 50fps to 59.8Hz by showing some frames more than once. I'd guess this strategy isn't sufficient to make up for a/v sync drift and it hits the tolerance -- issues with begin frame times being one of the causes for the strategy breaking down.

- dale

[Neil Kronlage]

> Were you seeing viz::BeginFrameArgs::frame_time that had the deltas of 16.74ms. Or was this arrival/processing time within the video code that had such deltas? 

Here are some traces of the times in GenerateBeginFrameArgs. I stashed off the last frame time to get the deltas between calls. You can see vsync_interval is fixed but the actual time between frames is higher:

07-19 09:41:38.931 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405660834 bogo-microseconds deadline: 2405677500 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.01674 s
07-19 09:41:38.944 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405677552 bogo-microseconds deadline: 2405694218 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.016718 s
07-19 09:41:38.960 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405694296 bogo-microseconds deadline: 2405710962 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.016744 s
07-19 09:41:38.977 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405711011 bogo-microseconds deadline: 2405727677 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.016715 s
07-19 09:41:38.994 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405727748 bogo-microseconds deadline: 2405744414 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.016737 s
07-19 09:41:39.011 28811 28872 E chromium: [ERROR:begin_frame_source.cc(118)] frame_time: 2405744482 bogo-microseconds deadline: 2405761148 bogo-microseconds vsync_interval: 0.016666 s (frame_time - last_frame_time): 0.016734 s

> I'll look at the algorithm test a bit more closely, it's been a long time since I wrote that.

Thanks for looking! Lmk what you find.

I can open a bug for the dropped frames in Chrome in this scenario if it helps.

[Neil Kronlage]

Here's a bug to track the dropped frame issue on Android: https://issues.chromium.org/issues/354101898

[Jonathan Ross]

Thanks for filing that.

With your confirmation that the `frame_time` is drifting I've filed https://issues.chromium.org/issues/355108924 to denote the `frame_time` vs `deadline` drift.