chrome://help Easter egg animation triggers 80 idle wakeups per second after finishing, sometimes |
||||||||||||||||
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.
,
May 27 2016
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
,
May 30 2016
+ compositor animations peoples.
,
May 31 2016
As an extra info: alancutter@ fixed that animation in js. https://codereview.chromium.org/1525953002
,
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_.
,
May 31 2016
This was done by putting breakpoints in the code so the answer is both. I'll look at thread IDs to get more understanding.
,
May 31 2016
+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
,
May 31 2016
loyso and ajuma should be able to help.
,
Jun 1 2016
Also, this can be related to some scheduler stuff: https://bugs.chromium.org/p/chromium/issues/detail?id=507754
,
Jun 1 2016
It sounds to me more like there's an animation left around trying to tick forever, which it should be cleaned up and destroyed.
,
Jun 1 2016
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!
,
Jun 1 2016
The settings page is WebGL, it should just be blink making an animation via css/html mechanisms.
,
Jun 1 2016
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
,
Jun 1 2016
Taking to try to repro and figure out why the animation is sticking around.
,
Jun 1 2016
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?
,
Jun 1 2016
,
Jun 2 2016
Thank you so much, ajuma@. I'm looking into this. Note: ajuma@ mentioned that it is reproducible on Mac with hi-dpi.
,
Jun 2 2016
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.
,
Jun 2 2016
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.
,
Jun 2 2016
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).
,
Jun 6 2016
,
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
,
Jun 7 2016
,
Jun 7 2016
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.
,
Jun 7 2016
53.0.2761.2 doesn't have the fix (it's branched off 398174, the fix is in 398209).
,
Jun 8 2016
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?
,
Jun 9 2016
,
Jun 9 2016
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 |
||||||||||||||||
Comment 1 by esprehn@chromium.org
, May 27 2016