ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback fails under load due to PipelineFull and VsyncWaiter registration race #190430

Failure log

[111/408] ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback (2209 ms)
[INFO:flutter/testing/test_timeout_listener.cc(75)] Test timeout of 300 seconds per test case will be enforced.
 [0;33mNote: Google Test filter = ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback
 [m [0;32m[==========]  [mRunning 1 test from 1 test suite.
 [0;32m[----------]  [mGlobal test environment set-up.
 [0;32m[----------]  [m1 test from ShellTest
 [0;32m[ RUN      ]  [mShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback
../../../flutter/shell/common/shell_unittests.cc:2322: Failure
Value of: is_on_begin_frame_called
  Actual: false
Expected: true

../../../flutter/shell/common/shell_unittests.cc:2299: Failure
Value of: is_secondary_callback_called
  Actual: true
Expected: false

 [0;31m[  FAILED  ]  [mShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback (971 ms)
 [0;32m[----------]  [m1 test from ShellTest (971 ms total)

Gemini's analysis below so take this with a grain of salt.

Description

ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback in engine/src/flutter/shell/common/shell_unittests.cc:2282-2334 is flaky under heavy load.

When running the test in isolation (--gtest_filter=ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback), it passes consistently in ~37 ms on an M3 Mac Studio Ultra. However, under high CPU load or when running the full shell_unittests suite, it fails intermittently with the following assertion errors:

../../../flutter/shell/common/shell_unittests.cc:2322: Failure
Value of: is_on_begin_frame_called
  Actual: false
Expected: true

../../../flutter/shell/common/shell_unittests.cc:2299: Failure
Value of: is_secondary_callback_called
  Actual: true
Expected: false

[  FAILED  ] ShellTest.SecondaryVsyncCallbackShouldBeCalledAfterVsyncCallback (971 ms)

Root Causes

The test failures show that the secondary vsync callback executed before Dart's onBeginFrame callback (NativeOnBeginFrame) was ever invoked.

There are two race conditions that cause this inversion under load:

1. Root Cause 1: PipelineFull in Animator::BeginFrame skips onBeginFrame while secondary callbacks still execute

When VsyncWaiter::FireCallback executes on a vsync interval, it sequentially posts two tasks to the UITaskRunner in FIFO order (vsync_waiter.cc:130-151):

1. P_task: The primary vsync callback, which invokes Animator::BeginFrame(...).
2. S_task: The secondary vsync callback(s).

When P_task runs on the UI thread, it executes Animator::BeginFrame (animator.cc:101-108):

if (!producer_continuation_) {
  producer_continuation_ = layer_tree_pipeline_->Produce();
  if (!producer_continuation_) {
    TRACE_EVENT0("flutter", "PipelineFull");
    RequestFrame();
    return;
  }
}

• Under heavy test suite contention, the rasterizer thread can lag behind in consuming items from the 2-deep layer_tree_pipeline_.
• If all pipeline slots are occupied, layer_tree_pipeline_->Produce() returns nullptr (!producer_continuation_).
• When !producer_continuation_ occurs, Animator::BeginFrame logs PipelineFull and returns immediately at line 107 without calling delegate_.OnAnimatorBeginFrame(...).
• Consequently, Dart's onBeginFrame (NativeOnBeginFrame) is skipped for that vsync while the frame request is retried on the next tick.
• However, S_task (the secondary vsync callback) was already posted to the UITaskRunner. It executes immediately after P_task returns, encountering is_on_begin_frame_called == false and failing the test at line 2322.
• When the pipeline clears on a subsequent vsync, NativeOnBeginFrame finally executes and fails at line 2299 because is_secondary_callback_called was already set to true.

2. Root Cause 2: Asymmetric Registration Between ScheduleSecondaryVsyncCallback and Animator::RequestFrame

The test schedules two callbacks sequentially on the UITaskRunner:

shell->GetEngine()->ScheduleSecondaryVsyncCallback(0, [&]() { ... });
shell->GetEngine()->ScheduleFrame();

• ScheduleSecondaryVsyncCallback is synchronous: It immediately calls VsyncWaiter::ScheduleSecondaryCallback (vsync_waiter.cc:53-85), which invokes AwaitVSyncForSecondaryCallback() -> VsyncWaiterFallback::AwaitVSync(). This calculates frame_start_time via SnapToNextTick (vsync_waiter_fallback.cc:16-24) and schedules a timer task (PostTaskForTime([FireCallback], frame_start_time)) on the UITaskRunner.
• ScheduleFrame is asynchronous: Engine::ScheduleFrame() calls Animator::RequestFrame(true). Instead of calling waiter_->AsyncWaitForVsync(...) synchronously, Animator::RequestFrame() posts an asynchronous task (PostTask([self->AwaitVSync()])) to the UITaskRunner (animator.cc:263-269). Only when that task runs does it call VsyncWaiter::AsyncWaitForVsync to set callback_.
• Under thread starvation or when frame_start_time snaps to Now(), the timer task for VsyncWaiter::FireCallback can be dequeued before Animator::AwaitVSync() has executed.
• When FireCallback runs while callback_ is still nullptr, it dispatches only the secondary callback on the first vsync, causing it to execute ahead of any primary frame callback.

Why This Happens Under Test Suite Contention

In isolation, the UI, Raster, and Platform threads have zero contention. T_await_vsync registers callback_ well before the 16.66 ms vsync timer fires, and the rasterizer pipeline is empty.

During full test suite execution, heavy CPU contention and multi-thread load cause:

1. Rasterizer pipeline backpressure (PipelineFull), causing Animator::BeginFrame to abort early and retry on the next vsync.
2. Message loop scheduling latency on UITaskRunner, exposing the registration race between ScheduleSecondaryVsyncCallback and Animator::RequestFrame.