New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 615471 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Closed: Jun 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: All
Pri: 2
Type: Bug

Blocking:
issue 618512



Sign in to add a comment

chrome://help Easter egg animation triggers 80 idle wakeups per second after finishing, sometimes

Project Member Reported by brucedaw...@chromium.org, May 27 2016

Issue description

if you go to chrome://help, click on the chrome logo, and wait for the animation to finish, you may see that that renderer tab continues to do context switches (idle wakeups) even though there is nothing visibly changing. Tracing with chrome://tracing shows tasks being posted from Scheduler::BeginImplFrame at 60 fps. Investigating the C++ code shows that this code seems to be what keeps the animations running:

bool AnimationHost::AnimateLayers(base::TimeTicks monotonic_time) {
  if (!NeedsAnimateLayers())
    return false;

and NeedsAnimateLayers returns true because active_element_to_animations_map_ is non-empty.

This behavior is not seen on all machines. On some operating systems, and especially when connecting with remote desktop (???) it is seen but not in other cases.

The logo animation easter egg was discussed on the original chrome://help context switch bug, including a link to the easter-egg code which is triggering the behavior:

https://bugs.chromium.org/p/chromium/issues/detail?id=612540#c9

It's not clear whether this is a bug in the Javascript or a Chrome bug.

The animation stops when the chrome://help tab is not visible.

This is a follow-on to  crbug.com/612540  and it will be assigned appropriately after more investigation is done.
 
What's calling setNeedsAnimate? We can track back from the stack trace of you can find one.
Owner: stanisc@chromium.org
Status: Assigned (was: Untriaged)
I'll take this for now to do the initial investigation.
I've traced calls to AnimationHost::DidActivateElementAnimations and AnimationHost::DidDeactivateElementAnimations that insert / remove entries to active_element_to_animations_map_ and it looks like the order is wrong:
Deactivate: 28
Deactivate: 30
Activate: 30
Deactivate: 30
Deactivate: 28
Activate: 30

This is when running release build on Windows 10 (on my dev workstation).
The number is element ID. The order seems to be timing sensitive. When more data is added to the trace the order of the last Activate/Deactivate calls sometimes flip.

Here are call stacks for the last two out of order Deactivate and Activate calls:

cc.dll!cc::AnimationHost::DidDeactivateElementAnimations
	cc.dll!cc::ElementAnimations::UpdateActivation
	cc.dll!cc::ElementAnimations::InitAffectedElementTypes
	cc.dll!cc::AnimationHost::RegisterPlayerForElement
	cc.dll!cc::AnimationPlayer::PushPropertiesTo
	cc.dll!cc::AnimationTimeline::PushPropertiesToImplThread
	cc.dll!cc::AnimationTimeline::PushPropertiesTo
	cc.dll!cc::AnimationHost::PushPropertiesToImplThread
	cc.dll!cc::AnimationHost::PushPropertiesTo
	cc.dll!cc::LayerTreeHost::FinishCommitOnImplThread
	cc.dll!cc::ProxyImpl::ScheduledActionCommit
	cc.dll!cc::Scheduler::ProcessScheduledActions
	cc.dll!cc::Scheduler::NotifyReadyToCommit
	cc.dll!cc::ProxyImpl::StartCommitOnImpl
	cc.dll!base::internal::Invoker<base::IndexSequence<0,1,2,3,4>,base::internal::BindState<base::internal::RunnableAdapter<void (__thiscall cc::ProxyImpl::*)(cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool)>,void __cdecl(cc::ProxyImpl *,cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool),base::WeakPtr<cc::ProxyImpl> &,cc::CompletionEvent *,cc::LayerTreeHost * &,base::TimeTicks &,bool>,base::internal::InvokeHelper<1,void,base::internal::RunnableAdapter<void (__thiscall cc::ProxyImpl::*)(cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool)> >,void __cdecl(void)>::Run
	base.dll!base::debug::TaskAnnotator::RunTask
	base.dll!base::MessageLoop::RunTask
	base.dll!base::MessageLoop::DoWork
	base.dll!base::MessagePumpDefault::Run
	base.dll!base::MessageLoop::RunHandler
	base.dll!base::RunLoop::Run
	base.dll!base::MessageLoop::Run
	base.dll!base::Thread::Run
	base.dll!base::Thread::ThreadMain
	base.dll!base::`anonymous namespace'::ThreadFunc
	kernel32.dll!@BaseThreadInitThunk@12
	ntdll.dll!__RtlUserThreadStart
	ntdll.dll!__RtlUserThreadStart@8


cc.dll!cc::AnimationHost::DidActivateElementAnimations
	cc.dll!cc::ElementAnimations::UpdateActivation
	cc.dll!cc::ElementAnimations::AddAnimation
	cc.dll!cc::ElementAnimations::PushNewAnimationsToImplThread
	cc.dll!cc::ElementAnimations::PushPropertiesTo
	cc.dll!cc::AnimationHost::PushPropertiesToImplThread
	cc.dll!cc::AnimationHost::PushPropertiesTo
	cc.dll!cc::LayerTreeHost::FinishCommitOnImplThread
	cc.dll!cc::ProxyImpl::ScheduledActionCommit
	cc.dll!cc::Scheduler::ProcessScheduledActions
	cc.dll!cc::Scheduler::NotifyReadyToCommit
	cc.dll!cc::ProxyImpl::StartCommitOnImpl
	cc.dll!base::internal::Invoker<base::IndexSequence<0,1,2,3,4>,base::internal::BindState<base::internal::RunnableAdapter<void (__thiscall cc::ProxyImpl::*)(cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool)>,void __cdecl(cc::ProxyImpl *,cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool),base::WeakPtr<cc::ProxyImpl> &,cc::CompletionEvent *,cc::LayerTreeHost * &,base::TimeTicks &,bool>,base::internal::InvokeHelper<1,void,base::internal::RunnableAdapter<void (__thiscall cc::ProxyImpl::*)(cc::CompletionEvent *,cc::LayerTreeHost *,base::TimeTicks,bool)> >,void __cdecl(void)>::Run
	base.dll!base::debug::TaskAnnotator::RunTask
	base.dll!base::MessageLoop::RunTask
	base.dll!base::MessageLoop::DoWork
	base.dll!base::MessagePumpDefault::Run
	base.dll!base::MessageLoop::RunHandler
	base.dll!base::RunLoop::Run
	base.dll!base::MessageLoop::Run
	base.dll!base::Thread::Run
	base.dll!base::Thread::ThreadMain
	base.dll!base::`anonymous namespace'::ThreadFunc
	kernel32.dll!@BaseThreadInitThunk@12
	ntdll.dll!__RtlUserThreadStart
	ntdll.dll!__RtlUserThreadStart@8

Cc: loyso@chromium.org vollick@chromium.org
Components: Internals>Compositing>Animation
+ compositor animations peoples.

Comment 4 by loyso@chromium.org, May 31 2016

Cc: alancutter@chromium.org
As an extra info: alancutter@ fixed that animation in js.
https://codereview.chromium.org/1525953002

Comment 5 by loyso@chromium.org, May 31 2016

stanisc@, did you trace main thread or impl thread or both? To understand the order, your tracing must be grouped by AnimationHost::thread_instance_.
This was done by putting breakpoints in the code so the answer is both. I'll look at thread IDs to get more understanding.
Cc: danakj@chromium.org
+danakj@

I am not familiar with this code. Who would be a proper owner?
Could this be related to  http://crbug.com/551138  ?

To answer the question above the last two out of order calls are both made from IMPL thread. I've also noticed that when this works correctly the last call that deactivates the animation comes from within OnBeginImplFrameDeadline. When this works incorrectly it seems there there is no OnBeginImplFrameDeadline at the end.

cc.dll!cc::AnimationHost::DidDeactivateElementAnimations
	cc.dll!cc::ElementAnimations::UpdateActivation
	cc.dll!cc::ElementAnimations::UpdateState
	cc.dll!cc::AnimationHost::UpdateAnimationState
	cc.dll!cc::LayerTreeHostImpl::UpdateAnimationState
	cc.dll!cc::ProxyImpl::DrawAndSwapInternal
	cc.dll!cc::ProxyImpl::ScheduledActionDrawAndSwapIfPossible
	cc.dll!cc::Scheduler::DrawAndSwapIfPossible
	cc.dll!cc::Scheduler::ProcessScheduledActions
	cc.dll!cc::Scheduler::OnBeginImplFrameDeadline
	cc.dll!base::internal::Invoker<base::IndexSequence<0>,base::internal::BindState<base::internal::RunnableAdapter<void (__thiscall cc::TileManager::*)(void)>,void __cdecl(cc::TileManager *),base::WeakPtr<cc::TileManager> >,base::internal::InvokeHelper<1,void,base::internal::RunnableAdapter<void (__thiscall cc::TileManager::*)(void)> >,void __cdecl(void)>::Run
	cc.dll!base::CancelableCallback<void __cdecl(void)>::Forward
	base.dll!base::debug::TaskAnnotator::RunTask
	base.dll!base::MessageLoop::RunTask
	base.dll!base::MessageLoop::DoWork
	base.dll!base::MessagePumpDefault::Run
	base.dll!base::MessageLoop::RunHandler
	base.dll!base::RunLoop::Run
	base.dll!base::MessageLoop::Run
	base.dll!base::Thread::Run
	base.dll!base::Thread::ThreadMain
	base.dll!base::`anonymous namespace'::ThreadFunc
	kernel32.dll!@BaseThreadInitThunk@12
	ntdll.dll!__RtlUserThreadStart
	ntdll.dll!__RtlUserThreadStart@8

Comment 8 by danakj@chromium.org, May 31 2016

Cc: ajuma@chromium.org
loyso and ajuma should be able to help.

Comment 9 by loyso@chromium.org, Jun 1 2016

Also, this can be related to some scheduler stuff: https://bugs.chromium.org/p/chromium/issues/detail?id=507754
It sounds to me more like there's an animation left around trying to tick forever, which it should be cleaned up and destroyed.
Cc: skyos...@chromium.org briander...@chromium.org
We don't have any Win-specific code in cc or blink animations.
brianderson@, skyostil@ - any comments for the info in #7 (no OnBeginImplFrameDeadline at the end)? Thanks in advance!
The settings page is WebGL, it should just be blink making an animation via css/html mechanisms.
It might help to capture a trace[1] with the cc.scheduler and cc.scheduler.debug categories turned on.

[1] https://www.chromium.org/developers/how-tos/trace-event-profiling-tool
Owner: ajuma@chromium.org
Taking to try to repro and figure out why the animation is sticking around.
Components: Blink>Animation
Owner: loyso@chromium.org
The problem is that the ElementAnimations for the spinner isn't getting destroyed even when the composited layer itself gets destroyed. This means there's a race between the animation getting marked for deletion and the layer being destroyed. If the layer gets destroyed first, then when we get to ElementAnimations::UpdateState we early out since has_element_in_active_list() returns false, so the animation never gets marked for deletion.

What's supposed to happen (as I understand it) is that Blink calls CompositorAnimationPlayer::detachLayer, which leads to cc::AnimationPlayer::UnregisterPlayer, which causes the main thread cc::ElementAnimations instance to get destroyed (and then the compositor instance gets destroyed during the next commit). But in this particular example, the call to CompositorAnimationPlayer::detachLayer doesn't happen.

It looks like the problem here is that since the element's style has an animation on it even after the animation is done, the blink::Animation instance for it isn't getting destroyed. If I toggle the style in dev tools (removing the animation on element "product-logo"), this does get destroyed, triggering a call to blink::Animation::destroyCompositorPlayer, which leads to CompositorAnimationPlayer::detachLayer.

loyso, would you be able to look into this more to figure out where the destroy call should be happening?

Since the composited layer is getting destroyed, blink::ElementAnimations::updateAnimationFlags must be correctly realizing that the animation is actually done, so perhaps we need logic there to also destroy the compositor player if it exists but there are no current animations?
Components: -Internals>Compositing>Animation
Labels: Update-Monthly
Labels: OS-Mac
Thank you so much, ajuma@. I'm looking into this. Note: ajuma@ mentioned that it is reproducible on Mac with hi-dpi.
The race condition explains why I was seeing or not seeing this behavior based on things that shouldn't have mattered, like whether I was connecting through remote desktop.

I'd be interested to know how frequently this bug is likely to be hitting in the wild - it's obviously much more important if it happens on web pages other than just chrome://help.
ajuma@, "even when the composited layer itself gets destroyed."
What are the circumstances for destroying the layer in this situation as per c#1?
Is it a PaintLayerCompositor::allocateOrClearCompositedLayerMapping call? What's the |reason| there? Does it happens if you bring chrome://help tab to background?

We had another issues for recreating CompositedLayerMapping like https://codereview.chromium.org/2010963003/ so we restart animations from there. It looks like we should just cancel them if composited layer gets destroyed.
Labels: -OS-Windows -OS-Mac OS-All
This also repros on linux in a release build (but I couldn't repro on a debug build). The minimum conditions seems to be a css animation (not a css transition) on transform, opacity, or filter, with non-infinite duration but with "animation-fill-mode: forwards" and no compositing reason other than the animation itself (so, for example, having a will-change:transform or a 3d transform on the element will prevent this bug from happening). Here's another example: https://jsfiddle.net/59e4vLc3/

The composited layer is destroyed because the PaintLayer with the animation no longer has any compositing reasons after the animation ends. So during the next compositing update (that is, when PaintLayerCompositor::updateIfNeededRecursive gets called), CompositingLayerAssigner::assignLayersToBackingsInternal gets called with this PaintLayer, the PaintLayer has no compositing reasons (that is, PaintLayer::getCompositingReasons returns CompositingReasonNone), so then allocateOrClearCompositedLayerMapping gets called with compositedLayerUpdate=RemoveOwnCompositedLayerMapping.

That is, the layer was created for reason CompositingReasonActiveAnimation, that reason no longer exists (since ComputedStyle::shouldCompositedForCurrentAnimations returns false, and this means that when blink::ElementAnimations::UpdateAnimationFlags was called during a style recalculation it did not call ComputedStyle::setHasCurrentTransformAnimation(true), so effect.isCurrent must have been false there).

It's unrelated to putting the tab into the background (the only reason that stops the ticking is that we don't tick animations for background tabs anymore, but as soon as the tab is brought back into the foreground the ticking resumes).
Status: Started (was: Assigned)
Project Member

Comment 22 by bugdroid1@chromium.org, Jun 7 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/638ef70330224e93f144c2adbd864ac786bf1e70

commit 638ef70330224e93f144c2adbd864ac786bf1e70
Author: loyso <loyso@chromium.org>
Date: Tue Jun 07 02:51:57 2016

CC Animation: Activate/deactivate ElementAnimations on Layer addition/removal.

This is a CC-side fix which can be useful for all CC clients.

Blink side: We will need to fix the race in CompositedLayerMapping destruction vs. CompositorAnimationPlayer detachment separately.

BUG= 615471 
CQ_INCLUDE_TRYBOTS=tryserver.blink:linux_blink_rel

Review-Url: https://codereview.chromium.org/2042713002
Cr-Commit-Position: refs/heads/master@{#398209}

[modify] https://crrev.com/638ef70330224e93f144c2adbd864ac786bf1e70/cc/animation/element_animations.cc
[modify] https://crrev.com/638ef70330224e93f144c2adbd864ac786bf1e70/cc/animation/element_animations.h
[modify] https://crrev.com/638ef70330224e93f144c2adbd864ac786bf1e70/cc/trees/layer_tree_host_impl_unittest.cc
[modify] https://crrev.com/638ef70330224e93f144c2adbd864ac786bf1e70/cc/trees/layer_tree_host_unittest_animation.cc

Status: Fixed (was: Started)
I tested with 53.0.2761.2 canary (64-bit) and I can still the bug, so it appears that it is not fixed.

That is, when I click on the Chrome icon on chrome://help it animates, stops animating, and the context switch count stays raised after the animation stops.
53.0.2761.2 doesn't have the fix (it's branched off 398174, the fix is in 398209).
Status: Verified (was: Fixed)
Right you are - I examined the history incorrectly.

I just checked in 53.0.2762.0 canary (64-bit) and I can no longer repro the bug (using the same steps that used to be 100%). Thank you for the fix.

Regarding this:

> Blink side: We will need to fix the race in CompositedLayerMapping
> destruction vs. CompositorAnimationPlayer detachment separately.

Is there a separate bug to track this?

Blocking: 618512
Yes, I've set up a new bug: https://bugs.chromium.org/p/chromium/issues/detail?id=618512

Thanks for verifying this issue!

Sign in to add a comment