1208385 - AnimationEffects sometimes get out of sync with their Animations

Status: RESOLVED FIXED

(Core :: DOM: Animation, defect)

Description

[Brian Birtles (:birtles)]

I've been debugging some test failures from part 11 of bug 1195180 that only seems to happen on try server with e10s on Linux.

Basically, we get in a situation where, if we remove the call to HasEndEventToQueue from Animation::ComposeStyle we fail to paint the last frame of the transition.

Here is an annotated log of what happens towards the end of the failure case:

>> nsRefreshDriver(0xa6c42200)::Tick
  DocumentTimeline::WillRefresh (1 animations)
  Animation::Tick (is finished: 0)
  Updating effect time from from 98.606202ms to 115.634366ms
  (The animation is 200ms long so it hasn't finished by this point)
<< nsRefreshDriver(0xa6c42200)::Tick (5)
(The (5) here indicates we completed the tick normally, no early returns)
Getting animation rule from RuleNodeWithReplacement
Calling EnsureStyleRuleFor from GetAnimationRule
Setting mStyleChanging to false
Setting aStyleChanging to true
Composing style using local time 115.634366ms
  Created style rule 0xa6c63a20
  Added to style rule 0xa6c63a20 with progress 0.578172
GetAnimationRule returning style rule 0xa6c63a20
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
(The (1) here refers to this early return: https://dxr.mozilla.org/mozilla-central/rev/001942e4617b2324bfa6cdfb1155581cbc3f0cc4/layout/base/nsRefreshDriver.cpp#1484
 i.e. we are stuck waiting for a paint)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
Getting animation rule from RuleNodeWithReplacement
Calling EnsureStyleRuleFor from GetAnimationRule
Setting mStyleChanging to false
NOT setting aStyleChanging true despite having an end event to queue (aStyleChanging: 0)
(Here is the problem! Animation is getting its time from its timeline which is using the latest refresh driver tick time. However, we didn't get a call to Animation::Tick due to the early return above, so we haven't updated the effect's time.)
Adding finished style to style rule (nil)
Composing style using local time 115.634366ms
  Created style rule 0xa6c63a90
  Added to style rule 0xa6c63a90 with progress 0.578172
  (So here, in the effect, we are still using the old time!)
GetAnimationRule returning style rule 0xa6c63a90
(In other words, the Animation thinks it has finished but the effect hasn't been given the finished time!)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
Doing standard RequestRestyle but mStyleChanging is false
Getting animation rule from RuleNodeWithReplacement
Calling EnsureStyleRuleFor from GetAnimationRule
Not updating style rule because mStyleChanging is false
GetAnimationRule returning style rule 0xa6c63a90
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
<< nsRefreshDriver(0xa6c42200)::Tick (1)
>> nsRefreshDriver(0xa6c42200)::Tick
  DocumentTimeline::WillRefresh (1 animations)
  Animation::Tick (is finished: 1)
  Updating effect from from 115.634366ms to 200.000000ms
  Doing standard RequestRestyle but mStyleChanging is false
  (mStyleChanging is false because when we visited Animation::ComposeStyle earlier on the Animation thought it was already finished)
  Queueing transitionend
  Removing animation because it is neither relevant nor needs ticks
  No one needs ticks, stopping to observe
  Taking snapshot
  Getting animation rule from RuleNodeWithReplacement
  Calling EnsureStyleRuleFor from GetAnimationRule
  Not updating style rule because mStyleChanging is false
  GetAnimationRule returning style rule 0xa6c63a90
<< nsRefreshDriver(0xa6c42200)::Tick (5)


Basically, what we should do is:

1. Store a pointer from effects to their animations
2. Store the timeline time on the *animation* not the *effect*
3. Make effects look up to their animations to get their time (rather than caching it locally)

That way an Animation's time will *only* update when it is ticked.

Comment 1

[Brian Birtles (:birtles)]

I had hoped to use an nsRefPtr to store the link from effect to animation but that creates a situation where in both Animation.h and KeyframeEffectReadOnly.h the referred to class needs to be a complete type.

I can think of at least three options here:

1. Just make the link a raw pointer for now. This will be fine until we start storing references to effects and expect them to keep their corresponding animations alive (which, I expect, will be pretty soon).

2. Move the necessary methods from KeyframeEffectReadOnly up to AnimationEffectReadOnly, make Animation store a pointer to AnimationEffectReadOnly, store the nsRefPtr on KeyframeEffectReadOnly, and add 'virtual Animation* GetAnimation()' to AnimationEffectReadOnly so it can get to its animation when it needs to.

3. Don't use nsRefPtr and do manual ref-counting inside KeyframeEffectReadOnly.

(1) is simplest but really just defers the problem (assuming we do the refactoring I expect us to).
(2) is most correct (we'll probably need to do it eventually) but introduces an extra virtual method call for otherwise simple methods like "IsInPlay", "IsInEffect" etc.
(3) avoids both problems but I'm not sure how popular manual refcounting is these days.

I'm going to do (1) for now since the refactoring I'm preempting might still change.

Comment 2

[Brian Birtles (:birtles)]

(In reply to Brian Birtles (:birtles) from comment #0)
> 2. Store the timeline time on the *animation* not the *effect*

I think we could probably store the time on the timeline itself.

Comment 3

[Brian Birtles (:birtles)]

(In reply to Brian Birtles (:birtles) from comment #2)
> (In reply to Brian Birtles (:birtles) from comment #0)
> > 2. Store the timeline time on the *animation* not the *effect*
> 
> I think we could probably store the time on the timeline itself.

The trouble with both these options is that time should still move even if the timeline is not longer observing the refresh driver.

Comment 4

[Brian Birtles (:birtles)]

(In reply to Brian Birtles (:birtles) from comment #3)
> (In reply to Brian Birtles (:birtles) from comment #2)
> > (In reply to Brian Birtles (:birtles) from comment #0)
> > > 2. Store the timeline time on the *animation* not the *effect*
> > 
> > I think we could probably store the time on the timeline itself.
> 
> The trouble with both these options is that time should still move even if
> the timeline is not longer observing the refresh driver.

Actually it turns out it is ok to store the time on the animation since none of the timing properties on the animation update when it is finished/paused/idle and in all other cases it will cause the refresh driver to tick.

Comment 5

[Brian Birtles (:birtles)]

Attachment: part 0 - Fix up some references to Web Animations spec

Comment 6

[Brian Birtles (:birtles)]

Attachment: part 1 - Store a pointer to the owning animation on each KeyframeEffect

We need to do this so effect can query their owning animation for the current
time and avoid falling out of sync. Furthermore, this pointer is needed
for a number of other bugs (e.g. bug 1166500 comment 12, or bug 1190235)
anyway.

Comment 7

[Brian Birtles (:birtles)]

Attachment: part 2 - Store the timeline time on an Animation on each tick

Comment 8

[Brian Birtles (:birtles)]

Attachment: part 3 - Remove stored parent time from KeyframeEffectReadOnly

Comment 9

[Brian Birtles (:birtles)]

Actually I'm not sure if we need or even want part 2. After a bit more thought, I'm concerned that when an animation finishes and no longer receives ticks, it will have an old timeline time. If we restart the animation, then any calculation which includes the old timeline time will cause us to jump on the next tick. I think so, anyway, but will write a test next week to check.

Comment 10

[Brian Birtles (:birtles)]

Comment on attachment 8668838 [details] [diff] [review]
part 2 - Store the timeline time on an Animation on each tick

Cancelling review for part 2 while I work out if it is needed or not.

Comment 11

[Brian Birtles (:birtles)]

Attachment: test-seek-after-finish.html

I can confirm that with part 2 applied, this test fails. The box should animate once, then, after 1s, jump back to the middle and animate again. With part 2, however, it doesn't jump back.

This is because with part 2 we cache the timeline time and we don't get ticks after the animation finishes so when we go to do the seek and calculate the required start time, we'll use the old timeline time which will give us the wrong result.

However, I don't think we actually need part 2 and these try runs seem to confirm it:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=b2c189dcb8d2
https://treeherder.mozilla.org/#/jobs?repo=try&revision=733a721fdf90

If we discover we *do* need part 2, then we will simply have to do the caching but force an update to the stored timeline time when we come to do calculations like setting the start time.

Unfortunately, I can't think of an easy way of turning this test case into something automated. The symptoms it looks for could occur if the main thread was simply bogged down. In order to distinguish between the two cases (bad calculation vs busy main thread), we'd need to make the test wait a long time. There may be a way, but I haven't thought of it yet.

Comment 12

[Brian Birtles (:birtles)]

Attachment: part 2 - Remove stored parent time from KeyframeEffectReadOnly and get the time directly from the owning animation

Just renumbering part 3 to part 2

Comment 13

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c51389e09230
https://hg.mozilla.org/integration/mozilla-inbound/rev/8770acc7fd9c
https://hg.mozilla.org/integration/mozilla-inbound/rev/ee3890805a77

Comment 14

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/c51389e09230
https://hg.mozilla.org/mozilla-central/rev/8770acc7fd9c
https://hg.mozilla.org/mozilla-central/rev/ee3890805a77