Investigating, thanks for the repro case!

So I've noticed several things while debugging this, like that we regularly unregister all element ids[1] and reregister them each PAC update. This doesn't seem particularly efficient and I'm hoping this won't always be the case. It may also be the reason for other strange animation behavior.

For example, the KeyframeModel for the crashing animation seems to be in the run_state_ WAITING_FOR_TARGET_AVAILABILITY when it crashes where without BGPT the run_state_ is not recreated every update, only changing on the first animation tick.

The key issue seems to be that we fail to mark the animation finished and remove it from ticking when the element id goes away. The process for removing from non BGPT is:

During AnimationHost::UpdateAnimationState:
1. KeyframeEffect::MarkFinishedKeyframeModels marks models which have not yet finished but have reached their finish time as run_state_ FINISHED.
2. In KeyframeEffect::MarkKeyframeModelsForDeletion we check whether all of the keyframe models in the given group have run_state_ FINISHED, if so we mark the keyframe models for deletion
3. In KeyframeEffect::UpdateTickingState we check that the run_state_ of all models is WAITING_FOR_DELETION and if so, remove the effect / animation.

Due to being in run_state_ WAITING_FOR_TARGET_AVAILABILITY it looks like KeyframeModel::IsFinishedAt would not return that the animation should be finished.

My guess as to what is happening is since we unregister the elements every frame when the animation finishes we unregister the animation's element id, the animation is failing to get marked as finished and get removed. I'm not certain yet though as there's a fair bit of jumping around code sections.

[1] https://cs.chromium.org/chromium/src/third_party/blink/renderer/platform/graphics/compositing/paint_artifact_compositor.cc?type=cs&q=paintartifactcompositor+unregisterallelementids&g=0&l=83

I just landed a patch to make us stop removing and re-adding all layers on every frame (https://crrev.com/593254) and I bet the unregister/re-register element id logic was just mirroring that. I think you can remove the unregister/re-register element id logic.

I'd still like to investigate the underlying cause just in case we'd be papering over a real problem for short lived animations for example.

I discovered that reverting https://chromium-review.googlesource.com/c/chromium/src/+/1091504 makes this test page succeed some or most of the time. What happens when things succeed is the following stack trace:
#0  0x00007fca719213e0 in cc::AnimationTimeline::SetNeedsPushProperties() (this=0x1e1e3bccf500) at ../../cc/animation/animation_timeline.cc:77
#1  0x00007fca71903c91 in cc::Animation::SetNeedsPushProperties() (this=0x1e1e3b79ba20) at ../../cc/animation/animation.cc:332
#2  0x00007fca7192c547 in cc::KeyframeEffect::SetNeedsPushProperties() (this=0x1e1e3bb9ff50) at ../../cc/animation/keyframe_effect.cc:77
#3  0x00007fca7192f2a6 in cc::KeyframeEffect::MarkFinishedKeyframeModels(base::TimeTicks) (this=0x1e1e3bb9ff50, monotonic_time=19 days, 15:07:16.955808) at ../../cc/animation/keyframe_effect.cc:1053
#4  0x00007fca7192ea48 in cc::KeyframeEffect::UpdateState(bool, cc::AnimationEvents*) (this=0x1e1e3bb9ff50, start_ready_keyframe_models=true, events=0x1e1e3b834020) at ../../cc/animation/keyframe_effect.cc:194
#5  0x00007fca71902e62 in cc::Animation::UpdateState(bool, cc::AnimationEvents*) (this=0x1e1e3b79ba20, start_ready_animations=true, events=0x1e1e3b834020) at ../../cc/animation/animation.cc:259
#6  0x00007fca71916b46 in cc::AnimationHost::UpdateAnimationState(bool, cc::MutatorEvents*) (this=0x1e1e3b7b3890, start_ready_animations=true, mutator_events=0x1e1e3b834020) at ../../cc/animation/animation_host.cc:394
#7  0x00007fca804ea8d9 in cc::LayerTreeHost::AnimateLayers(base::TimeTicks) (this=0x1e1e3bc28020, monotonic_time=19 days, 15:07:16.955808) at ../../cc/trees/layer_tree_host.cc:971

This sets needs push properties on the timeline which on the impl side of the commit, does the following:
#0  0x00007fca71935d2f in cc::KeyframeEffect::RemoveKeyframeModelsCompletedOnMainThread(cc::KeyframeEffect*) const (this=0x1e1e3bb9ff50, keyframe_effect_impl=0x1e1e3bd34b60) at ../../cc/animation/keyframe_effect.cc:752
#1  0x00007fca719361e8 in cc::KeyframeEffect::PushPropertiesTo(cc::KeyframeEffect*) (this=0x1e1e3bb9ff50, keyframe_effect_impl=0x1e1e3bd34b60) at ../../cc/animation/keyframe_effect.cc:798
#2  0x00007fca719020b9 in cc::Animation::PushPropertiesToImplThread(cc::Animation*) (this=0x1e1e3b79ba20, animation_impl=0x1e1e3bd5d720) at ../../cc/animation/animation.cc:195
#3  0x00007fca719029bc in cc::Animation::PushPropertiesTo(cc::Animation*) (this=0x1e1e3b79ba20, animation_impl=0x1e1e3bd5d720) at ../../cc/animation/animation.cc:247
#4  0x00007fca719238f3 in cc::AnimationTimeline::PushPropertiesToImplThread(cc::AnimationTimeline*) (this=0x1e1e3bccf500, timeline_impl=0x1e1e3b957ab0) at ../../cc/animation/animation_timeline.cc:133
#5  0x00007fca71922f36 in cc::AnimationTimeline::PushPropertiesTo(cc::AnimationTimeline*) (this=0x1e1e3bccf500, timeline_impl=0x1e1e3b957ab0) at ../../cc/animation/animation_timeline.cc:87
#6  0x00007fca71915129 in cc::AnimationHost::PushPropertiesToImplThread(cc::AnimationHost*) (this=0x1e1e3b7b3890, host_impl=0x1e1e3b7aae30) at ../../cc/animation/animation_host.cc:237
#7  0x00007fca719146de in cc::AnimationHost::PushPropertiesTo(cc::MutatorHost*) (this=0x1e1e3b7b3890, mutator_host_impl=0x1e1e3b7aae30) at ../../cc/animation/animation_host.cc:195
#8  0x00007fca804e006f in cc::LayerTreeHost::FinishCommitOnImplThread(cc::LayerTreeHostImpl*) (this=0x1e1e3bc28020, host_impl=0x1e1e3bcc0820) at ../../cc/trees/layer_tree_host.cc:360
#9  0x00007fca805e0db3 in cc::ProxyImpl::ScheduledActionCommit() (this=0x1e1e3b9e38e0) at ../../cc/trees/proxy_impl.cc:557
#10 0x00007fca803e4e47 in cc::Scheduler::ProcessScheduledActions() (this=0x1e1e3bc21520) at ../../cc/scheduler/scheduler.cc:790
#11 0x00007fca803e63d8 in cc::Scheduler::NotifyReadyToCommit() (this=0x1e1e3bc21520) at ../../cc/scheduler/scheduler.cc:163
#12 0x00007fca805dc0be in cc::ProxyImpl::NotifyReadyToCommitOnImpl(cc::CompletionEvent*, cc::LayerTreeHost*, base::TimeTicks, bool) (this=0x1e1e3b9e38e0, completion=0x7fff1def9b88, layer_tree_host=0x1e1e3bc28020, main_thread_start_time=19 days, 15:07:16.958549, hold_commit_for_activa
tion=false) at ../../cc/trees/proxy_impl.cc:267

This sets the keyframe effect to no longer affect pending elements. So this seems to be exactly how we are supposed to observe that the animation does not affect elements on the pending tree.

I've debugged the other failure in my local testing. When the compositor notifies the main thread of the animation start time, it calls:
#0  0x00007f00d595568a in blink::AnimationClock::CurrentTime() (this=0x49664e61888) at ../../third_party/blink/renderer/core/animation/animation_clock.cc:56
#1  0x00007f00d5a2e83a in blink::DocumentTimeline::CurrentTimeInternal(bool&) (this=0xbe22dfb77f0, is_null=@0x7ffe5c4aa697: false)
    at ../../third_party/blink/renderer/core/animation/document_timeline.cc:234
#2  0x00007f00d5a2e149 in blink::DocumentTimeline::CurrentTimeInternal() (this=0xbe22dfb77f0)
    at ../../third_party/blink/renderer/core/animation/document_timeline.cc:249
#3  0x00007f00d5a2e9f5 in blink::DocumentTimeline::EffectiveTime() (this=0xbe22dfb77f0)
    at ../../third_party/blink/renderer/core/animation/document_timeline.cc:253
#4  0x00007f00d5948c53 in blink::Animation::CalculateCurrentTime() const (this=0xbe22dfba870)
    at ../../third_party/blink/renderer/core/animation/animation.cc:466
#5  0x00007f00d594b5a9 in blink::Animation::SetStartTimeInternal(base::Optional<double>) (this=0xbe22dfba870, new_start_time=...)
    at ../../third_party/blink/renderer/core/animation/animation.cc:495
#6  0x00007f00d594b2ab in blink::Animation::NotifyStartTime(double) (this=0xbe22dfba870, timeline_time=3.3761819999199361)
    at ../../third_party/blink/renderer/core/animation/animation.cc:432
#7  0x00007f00d594ac7c in blink::Animation::NotifyCompositorStartTime(double) (this=0xbe22dfba870, timeline_time=3.3761819999199361)
    at ../../third_party/blink/renderer/core/animation/animation.cc:421
#8  0x00007f00d5a7f033 in blink::PendingAnimations::NotifyCompositorAnimationStarted(double, int) (this=0xbe22dfb7918, monotonic_animation_start_time=1696027.6228479999, compositor_group=2) at ../../third_party/blink/renderer/core/animation/pending_animations.cc:163
#9  0x00007f00d594e06d in blink::Animation::NotifyAnimationStarted(double, int) (this=0xbe22dfbb268, monotonic_time=1696027.6228479999, group=2)
    at ../../third_party/blink/renderer/core/animation/animation.cc:1114
#10 0x00007f00d2dd88a0 in blink::CompositorAnimation::NotifyAnimationStarted(base::TimeTicks, int, int) (this=0x28b9b7680d40, monotonic_time=19 days, 15:07:07.622848, target_property=0, group=2) at ../../third_party/blink/renderer/platform/animation/compositor_animation.cc:93
#11 0x00007f00d2547308 in cc::Animation::NotifyKeyframeModelStarted(cc::AnimationEvent const&) (this=0x28b9b76bdc20, event=...)
    at ../../cc/animation/animation.cc:286
#12 0x00007f00d2575ee8 in cc::KeyframeEffect::NotifyKeyframeModelStarted(cc::AnimationEvent const&) (this=0x28b9b776af50, event=...)
    at ../../cc/animation/keyframe_effect.cc:390
#13 0x00007f00d2569f57 in cc::ElementAnimations::NotifyAnimationStarted(cc::AnimationEvent const&) (this=0x28b9b71b1980, event=...)
    at ../../cc/animation/element_animations.cc:164
#14 0x00007f00d255b46e in cc::AnimationHost::SetAnimationEvents(std::__1::unique_ptr<cc::MutatorEvents, std::__1::default_delete<cc::MutatorEvents> >) (this=0x28b9b707fc50, mutator_events=...) at ../../cc/animation/animation_host.cc:426
#15 0x00007f00e11290a4 in cc::LayerTreeHost::SetAnimationEvents(std::__1::unique_ptr<cc::MutatorEvents, std::__1::default_delete<cc::MutatorEvents> >) (this=0x28b9b7660020, events=std::__1::unique_ptr<cc::MutatorEvents> = 0x0 <nullptr>) at ../../cc/trees/layer_tree_host.cc:602
#16 0x00007f00e122be46 in cc::ProxyMain::SetAnimationEvents(std::__1::unique_ptr<cc::MutatorEvents, std::__1::default_delete<cc::MutatorEvents> >) (this=0x28b9b759cec0, events=std::__1::unique_ptr<cc::MutatorEvents> = 0x0 <nullptr>) at ../../cc/trees/proxy_main.cc:93

In this particular case, the animation started at monotonic time 1696027.622848s and the current frame begin time is 1696027.639514s. This means that the animation is at local time 16.666ms.

However, when the start time is set and the main thread goes to calculate the current timeline time the AnimationClock no longer returns the current frame time as the task_for_which_time_was_calculated_ != currently_running_task_. This means we calculate a current effective time which is later than the frame begin time, putting the animation at a local time past the end of the animation.

With the animation complete, the new main frame no longer composites the "formerly" animated element.

However, since according to the BeginMainFrame timestamp the animation should still be in effect, we expect the new pending tree to have active animations.

The bug seems to be that the currently_running_task has advanced since the animation clock time was set to the frame time. This might have the same root cause as issue 785940.

There are two tasks posted for starting the next main frame:

cc::ProxyImpl::ScheduledActionSendBeginMainFrame posts a task to run ProxyMain::BeginMainFrame
cc::ProxyImpl::PostAnimationEventsToMainThreadOnImplThread posts a task to run ProxyMain::SetAnimationEvents

The fix may be as simple as not posting SetAnimationsEvents but instead passing the animation events with the BeginMainFrame so that the entire task runs with the correct BeginFrame timestamp.

Actually since the PostAnimationEventsToMainThread is scheduled during the draw it seems like the timeline of what happens is:

SendBeginMainFrame (t1)
ScheduledActionDraw (main took too long presumably)
- PostAnimationEventsToMain

Then we receive both of the events in order on main. Since the main frame's frame time is still t1 the animation events should use that time when calculating the current time of the animations. Instead, they incorrectly update to the current time.

Maybe this means PostAnimationEventsToMain should actually post the beginframe time which the animation events are for? Essentially, if we are going to generate a main frame we should not use a future frame timestamp.

Actually, it shouldn't be necessary fix the per-task timing since the BeginMainFrame is synchronous. The main issue is that some of the animations code is using the animation clock (like PageAnimator::ServiceScriptedAnimations) (which is ahead of rAF) and some of it is not (LayerTreeHost::AnimateLayers). This results in different answers for questions like is this animation still ticking.

We should probably fetch the document timeline clock time and pass that to the LayerTreeHost since that is the currently authoritative time for main thread animation state.

Alright, I've separated the AnimateLayers timing issue into  issue 891141  and uploaded a patch there which resolves that.

After that, https://chromium-review.googlesource.com/c/chromium/src/+/1256422 fixes the crash on Gmail.

I just need to add appropriate tests and ensure that the animations layout tests which the original patch were working around no longer fail with the fixes in place.

With the fix I landed for  issue 891141  we correctly finish the animation resolving this crash.