I've noticed on my unagi that I'm seeing a flood of the following messages: [Parent 109] WARNING: should already have refreshed style rule: 'ea->mStyleRuleRefreshTime == mPresContext->RefreshDriver()->MostRecentRefresh()', file /home/work/B2G-unagi/birch/layout/style/nsAnimationManager.cpp, line 988 whenever I do pretty much anything in the UI on my unagi phone. This is running using the master branch of gaia on birch (essentially m-c)

dougt pointed this out to me less than 24 hours ago. I'm guessing it's a pretty recent regression?

I noticed it late last week when I updated my tree. My previous tree update (due to PTO) would have been at least 2-3 weeks prior to that.

nrc, any chance you could look into this?

(In reply to David Baron [:dbaron] (don't cc:, use needinfo? instead) from comment #3) > nrc, any chance you could look into this? Yes, I was intending to but I've been acquiring quite the queue of bugs while I try to finish off OMTC d3d9. That should land today so I should have time for this next week.

I couldn't repro because my b2g setup is a bit messed up right now. But this looks wrong and like it could cause the warnings.

Comment on attachment 785581 [details] [diff] [review] possible fix I think this code is right -- it's saying that we know we need to rebuild the animation rule, but we're not doing it here. In particular, CheckAnimationRule is how we detect that there's been a style change, which may come between refresh cycles. That style change might in turn require that we update our animation data. The change you're proposing would instead be saying that we have no animation rule and that's correct for the duration of this refresh cycle. (There used to be a brief comment added in https://hg.mozilla.org/mozilla-central/rev/1c17ed72040c which could have been expanded to explain that better... but at some point it instead got removed!)

(In reply to David Baron [:dbaron] (don't cc:, use needinfo? instead) from comment #6) > Comment on attachment 785581 [details] [diff] [review] > possible fix > > I think this code is right -- it's saying that we know we need to rebuild > the animation rule, but we're not doing it here. In particular, > CheckAnimationRule is how we detect that there's been a style change, which > may come between refresh cycles. That style change might in turn require > that we update our animation data. > > The change you're proposing would instead be saying that we have no > animation rule and that's correct for the duration of this refresh cycle. > > (There used to be a brief comment added in > https://hg.mozilla.org/mozilla-central/rev/1c17ed72040c which could have > been expanded to explain that better... but at some point it instead got > removed!) Yes, you are right. I didn't understand what was going on here, but that clears it up, thanks.

I think what is going on here is that if a style is throttled, then we can call EnsureStyleRuleFor with aIsThrottled == true and then we don't update the style or the refresh time (because that is what throttling does). But we can then end up calling GetAnimationRule before we do a mini-flush and so the refresh time is still not up to date and we get the warning (which used to abort, it was probably wrong of me to change it). More detail: before throttling existed, each refresh tick would call EnsureStyleRuleFor (via FlushAnimations) and that would make the style current. For the current tick, during which we might call GetAnimationRule. Now Ensure... does not in fact ensure the style rule is up to date, unless we force not to throttle (e.g., from a mini-flush). I think the solution is to call a non-throttling EnsureStyleRule in GetAnimationRule (like we do for transitions). For non-throttled animations that should be very cheap because the refresh time will be up to date. There are also a few vaguely related and very minor refactorings in this patch. I can put them somewhere else if you prefer, or just drop them.

Comment on attachment 785916 [details] [diff] [review] different fix >+// post-condition: !aIsThrottled => mStyleRuleRefreshTime == aRefreshTime We have a nice NS_POSTCONDITION macro for this. Please use it :-) (I admit that requires putting it in 2 places, but that's fine.) >+ MOZ_ASSERT(ea->mStyleRuleRefreshTime == refreshTime, >+ "Violated EnsureStyleRuleFor post-condition"); Probably better making this NS_ASSERTION; no reason for it to be fatal. >- NS_WARN_IF_FALSE(ea->mStyleRuleRefreshTime == >- mPresContext->RefreshDriver()->MostRecentRefresh(), >- "should already have refreshed style rule"); >+ ea->EnsureStyleRuleFor(mPresContext->RefreshDriver()->MostRecentRefresh(), >+ mPendingEvents, >+ false); >+ CheckNeedsRefresh(); So I'm assuming this bit is the actual fix and the rest is the refactoring. (Though you should really get in the habit of using a stack of patches for that sort of thing.) From comment 7: > But we can then end up calling GetAnimationRule before we do a > mini-flush and so the refresh time is still not up to date and we get > the warning (which used to abort, it was probably wrong of me to > change it). I guess the question is: how can we call GetAnimationRule before we do a mini-flush? (At a minimum, what's the stack, and perhaps more to explain how it's happening.) (I'm a little worried that papering over this might lead to us disabling throttling in some cases where we want it.) Marking as review- for now to prompt an answer to that question, although re-requesting review on the same patch might be the right response.

Stack trace to GetAnimationRule (not very helpful, tbh): #0 nsAnimationManager::GetAnimationRule (this=0x7fffc46cbb00, aElement=0x7fffc38b8b80, aPseudoType=nsCSSPseudoElements::ePseudo_NotPseudoElement) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:992 #1 0x00007ffff0063099 in nsAnimationManager::RulesMatching (this=0x7fffc46cbb00, aData=0x7fffffffb240) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:488 #2 0x00007ffff01528e7 in EnumRulesMatching<ElementRuleProcessorData> ( aProcessor=0x7fffc46cbb00, aData=0x7fffffffb240) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:657 #3 0x00007ffff014e870 in nsStyleSet::FileRules (this=0x7fffc3151f00, aCollectorFunc=0x7ffff01528b1 <EnumRulesMatching<ElementRuleProcessorData>(nsIStyleRuleProcessor*, void*)>, aData=0x7fffffffb240, aElement=0x7fffc38b8b80, aRuleWalker=0x7fffffffb220) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:1018 #4 0x00007ffff014f193 in nsStyleSet::ResolveStyleFor (this=0x7fffc3151f00, aElement=0x7fffc38b8b80, aParentContext=0x7fffcc047be0, aTreeMatchContext=...) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:1175 #5 0x00007fffefe165d5 in mozilla::ElementRestyler::RestyleSelf ( this=0x7fffffffb4c0, aRestyleHint=eRestyle_Self) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleManager.cpp:2265 #6 0x00007fffefe15ba9 in mozilla::ElementRestyler::Restyle (this=0x7fffffffb4c0, aRestyleHint=eRestyle_Self) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleManager.cpp:2066 #7 0x00007fffefe17dc5 in mozilla::RestyleManager::ComputeStyleChangeFor ( this=0x7fffc32dbc00, aFrame=0x7fffcb742858, aChangeList=0x7fffffffb760, aMinChange=(unknown: 0), aRestyleTracker=..., aRestyleDescendants=false) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleManager.cpp:2717 #8 0x00007fffefe127b2 in mozilla::RestyleManager::RestyleElement ( this=0x7fffc32dbc00, aElement=0x7fffc38b8b80, aPrimaryFrame=0x7fffcb742858, aMinHint=(unknown: 0), aRestyleTracker=..., aRestyleDescendants=false) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleManager.cpp:795 #9 0x00007fffefe1c517 in mozilla::RestyleTracker::ProcessOneRestyle ( this=0x7fffc32dbd98, aElement=0x7fffc38b8b80, aRestyleHint=eRestyle_Self, aChangeHint=(unknown: 0)) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleTracker.cpp:123 #10 0x00007fffefe1ca36 in mozilla::RestyleTracker::DoProcessRestyles ( this=0x7fffc32dbd98) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleTracker.cpp:205 #11 0x00007fffefe0f9cb in mozilla::RestyleTracker::ProcessRestyles ( this=0x7fffc32dbd98) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleTracker.h:216 #12 0x00007fffefe13b46 in mozilla::RestyleManager::ProcessPendingRestyles ( this=0x7fffc32dbc00) at /home/ncameron/hdd2/firefox/src/layout/base/RestyleManager.cpp:1358 #13 0x00007fffefee64dc in PresShell::FlushPendingNotifications ( this=0x7fffc3818400, aFlush=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:3851 #14 0x00007fffeff04723 in nsRefreshDriver::Tick (this=0x7fffc32dc000, aNowEpoch=1375938487672628, aNowTime=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:1171 #15 0x00007fffeff02259 in mozilla::RefreshDriverTimer::TickDriver ( driver=0x7fffc32dc000, jsnow=1375938487672628, now=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:171 #16 0x00007fffeff021ad in mozilla::RefreshDriverTimer::Tick (this=0x7fffdab74840) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:163 ...

Call stack for Cannot_Throttle call to EnsureStyleRule (this is the only call I found that should trigger updating the style rule, not sure how connected this is to the above call stack because the bug is intermittent): #0 ElementAnimations::EnsureStyleRuleFor (this=0x7fffc32b4680, aRefreshTime=..., aEventsToDispatch=..., aIsThrottled=false) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:213 #1 0x00007ffff0064a9b in nsAnimationManager::FlushAnimations ( this=0x7fffc1ae2600, aFlags=mozilla::css::CommonAnimationManager::Cannot_Throttle) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:1066 #2 0x00007fffefee6429 in PresShell::FlushPendingNotifications ( this=0x7fffc46be000, aFlush=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:3841 #3 0x00007fffefee5fec in PresShell::FlushPendingNotifications ( this=0x7fffc46be000, aType=Flush_InterruptibleLayout) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:3736 #4 0x00007fffefee5f13 in PresShell::HandlePostedReflowCallbacks ( this=0x7fffc46be000, aInterruptible=true) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:3704 #5 0x00007fffefef33f0 in PresShell::DidDoReflow (this=0x7fffc46be000, aInterruptible=true, aWasInterrupted=false) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:7670 #6 0x00007fffefef46f0 in PresShell::ProcessReflowCommands (this=0x7fffc46be000, aInterruptible=true) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:8003 #7 0x00007fffefee6687 in PresShell::FlushPendingNotifications ( this=0x7fffc46be000, aFlush=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsPresShell.cpp:3890 #8 0x00007fffeff04948 in nsRefreshDriver::Tick (this=0x7fffc462f400, aNowEpoch=1375939824164809, aNowTime=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:1192 #9 0x00007fffeff02259 in mozilla::RefreshDriverTimer::TickDriver ( driver=0x7fffc462f400, jsnow=1375939824164809, now=...) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:171 #10 0x00007fffeff021ad in mozilla::RefreshDriverTimer::Tick (this=0x7fffdab74840) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:163 #11 0x00007fffeff0227f in mozilla::RefreshDriverTimer::TimerTick ( aTimer=0x7fffdafdde80, aClosure=0x7fffdab74840) at /home/ncameron/hdd2/firefox/src/layout/base/nsRefreshDriver.cpp:188 #12 0x00007ffff1d7221e in nsTimerImpl::Fire (this=0x7fffdafdde80) at /home/ncameron/hdd2/firefox/src/xpcom/threads/nsTimerImpl.cpp:544 #13 0x00007ffff1d72589 in nsTimerEvent::Run (this=0x7fffd481a1d0) at /home/ncameron/hdd2/firefox/src/xpcom/threads/nsTimerImpl.cpp:628 #14 0x00007ffff1d6a80a in nsThread::ProcessNextEvent (this=0x7ffff6a754a0, mayWait=true, result=0x7fffffffc7ef) at /home/ncameron/hdd2/firefox/src/xpcom/threads/nsThread.cpp:622 #15 0x00007ffff1cee2d4 in NS_ProcessNextEvent (thread=0x7ffff6a754a0, mayWait=true) at /home/ncameron/hdd2/firefox/obj-debug/xpcom/build/nsThreadUtils.cpp:238

I don't really know the dynamics of reflow enough to analyse what is going on here. But, some observations: I think (hope) I was wrong about us missing a mini-flush. We never get mini-flushes, since mini-flushes only happen when a transition is running. For animations with no transitions we might never get a mini-flush. Our style rule is updated from PresShell::FlushPendingNotifications if we are flushing animations in this flush and the pres context thinks that there are animations which are not up to date (http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#3841). The call to GetAnimationRule is coming from the call to ProcessPendingRestyles a few lines later in FlushPendingNotifications (http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#3878). Presumably we only hit the warning if we don't do the above flush of animations. I'm not sure if anything should prevent us going down the route of the first call stack if the above two conditions gating the animation flush don't hold. In the second stack we do this at frame 7 then re-enter FlushPendingNotifications at frame 2 which leads to the non-throttled flush. I have no idea if this is significant. So, the important and un-resolved question is why we end up at GetAnimationRule without first calling EnsureStyleRuleFor with aIsThrottled=false. And whether this it is expected for this to be happen. I don't see any reason why it shouldn't, but I do not understand what is going on with all the refreshing and flushing and so forth. If it is expected that this might happen, then I think the fix in the patch (calling EnsureStyleRuleFor) is correct. If it isn't, then we need to find some way to enforce that we ensure before we get.

The stacks are certainly useful at least for the line numbers within nsRefreshDriver::Tick, which seem to match up to the code in https://hg.mozilla.org/mozilla-central/file/55b6b3b78d37/layout/base/nsRefreshDriver.cpp

I came back to look at this and can no longer reproduce. My test case for desktop is now warning free and instrumenting a b2g build with printfs yielded nothing, so it seems to have spontaneously resolved. Given that this kind of randomly started happening I'm not that surprised and I expect it will start happening again. I would really like to know why it stopped. Nothing significant has changed in nsAnimationManager, so I suspect some subtle change in the reflow logic has affected this. I really need to catch this is a debugger to get any further with resolving it, so for now I guess we just leave it be. dhylands: have you observed this warning recently? dbaron: any idea what might have stopped this happening?

So (thanks to heycam) I can repro the warning by running layout/style/tests/test_value_storage.html with OMTA disabled. That is kind of weird because previously we only observed the warning with OMTA on. I'll try and catch it in a debugger and investigate it further.

The non-OMTA case has a different stack, it is: #0 0x00002aaaae4c2ed9 in nsAnimationManager::GetAnimationRule ( this=0x2aaad2696290, aElement=0x2aaad004ace0, aPseudoType=nsCSSPseudoElements::ePseudo_NotPseudoElement) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:992 #1 0x00002aaaae4c1993 in nsAnimationManager::RulesMatching ( this=0x2aaad2696290, aData=0x7fffffff8c40) at /home/ncameron/hdd2/firefox/src/layout/style/nsAnimationManager.cpp:488 #2 0x00002aaaae5b1384 in EnumRulesMatching<ElementRuleProcessorData> ( aProcessor=0x2aaad2696290, aData=0x7fffffff8c40) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:658 #3 0x00002aaaae5ade0e in nsStyleSet::FileRules (this=0x2aaad30bc300, aCollectorFunc=0x2aaaae5b134e <EnumRulesMatching<ElementRuleProcessorData>(nsIStyleRuleProcessor*, void*)>, aData=0x7fffffff8c40, aElement=0x2aaad004ace0, aRuleWalker=0x7fffffff8c20) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:1019 #4 0x00002aaaae5ae731 in nsStyleSet::ResolveStyleFor (this=0x2aaad30bc300, aElement=0x2aaad004ace0, aParentContext=0x2aaad4aa6268, aTreeMatchContext=...) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:1176 #5 0x00002aaaae5ae58e in nsStyleSet::ResolveStyleFor (this=0x2aaad30bc300, aElement=0x2aaad004ace0, aParentContext=0x2aaad4aa6268) at /home/ncameron/hdd2/firefox/src/layout/style/nsStyleSet.cpp:1159 #6 0x00002aaaae535c4d in nsComputedDOMStyle::GetStyleContextForElementNoFlush (aElement=0x2aaad004ace0, aPseudo=0x0, aPresShell=0x2aaad244b400, aStyleType=nsComputedDOMStyle::eAll) at /home/ncameron/hdd2/firefox/src/layout/style/nsComputedDOMStyle.cpp:349 #7 0x00002aaaae535995 in nsComputedDOMStyle::GetStyleContextForElement ( aElement=0x2aaad004ace0, aPseudo=0x0, aPresShell=0x2aaad244b400, aStyleType=nsComputedDOMStyle::eAll) at /home/ncameron/hdd2/firefox/src/layout/style/nsComputedDOMStyle.cpp:287 #8 0x00002aaaae536617 in nsComputedDOMStyle::GetPropertyCSSValue ( this=0x2aaad4aae080, aPropertyName=..., aRv=...) at /home/ncameron/hdd2/firefox/src/layout/style/nsComputedDOMStyle.cpp:550 #9 0x00002aaaae53583b in nsComputedDOMStyle::GetPropertyValue ( this=0x2aaad4aae080, aPropertyName=..., aReturn=...) at /home/ncameron/hdd2/firefox/src/layout/style/nsComputedDOMStyle.cpp:250 #10 0x00002aaaafda091b in nsICSSDeclaration::GetPropertyValue ( this=0x2aaad4aae080, aPropName=..., aValue=..., rv=...) at /home/ncameron/hdd2/firefox/src/layout/style/nsICSSDeclaration.h:126

In the non-OMTA case, we call GetAnimationRules via nsComputedDOMStyle::GetStyleContextForElement which calls FlushPendingNotifications. However, because OMTA is not enabled, FlushPendingNotifications does not call FlushAnimations and so the animations are not up to date. When FlushPendingNotifications is called from the refresh driver, it is called after WillRefresh on the animation manager which will update the animations if we are non-OMTA. In this case we hit the warning because we have not done so. The patch on this bug would fix this issue. But perhaps there are other classes which expect to have WillRefresh called in such a situation? But it seems to me (and this is where I am guessing really), that expecting WillRefresh to be called before GetAnimationRule is a bit too optimistic. dbaron - what do you think? None of this helps with the OMTA case, unfortunately.

(In reply to Nick Cameron [:nrc] from comment #14) > I came back to look at this and can no longer reproduce. My test case for > desktop is now warning free and instrumenting a b2g build with printfs > yielded nothing, so it seems to have spontaneously resolved. Given that this > kind of randomly started happening I'm not that surprised and I expect it > will start happening again. I would really like to know why it stopped. > Nothing significant has changed in nsAnimationManager, so I suspect some > subtle change in the reflow logic has affected this. I really need to catch > this is a debugger to get any further with resolving it, so for now I guess > we just leave it be. > > dhylands: have you observed this warning recently? > > dbaron: any idea what might have stopped this happening? I resync'd my tree this morning for my unagi. From bootup until the screen blanks, I observed 682 occurences of this message, so yes its still happening. I'm not sure if its relevant or not, but my unagi build is a debug build. It generates so much spam that I have to locally patch my tree to comment out the line that generates the warning, otherwise my logs are essentially useless.

(In reply to Dave Hylands [:dhylands] from comment #18) > (In reply to Nick Cameron [:nrc] from comment #14) > > I came back to look at this and can no longer reproduce. My test case for > > desktop is now warning free and instrumenting a b2g build with printfs > > yielded nothing, so it seems to have spontaneously resolved. Given that this > > kind of randomly started happening I'm not that surprised and I expect it > > will start happening again. I would really like to know why it stopped. > > Nothing significant has changed in nsAnimationManager, so I suspect some > > subtle change in the reflow logic has affected this. I really need to catch > > this is a debugger to get any further with resolving it, so for now I guess > > we just leave it be. > > > > dhylands: have you observed this warning recently? > > > > dbaron: any idea what might have stopped this happening? > > I resync'd my tree this morning for my unagi. From bootup until the screen > blanks, I observed 682 occurences of this message, so yes its still > happening. > Thanks for checking! > I'm not sure if its relevant or not, but my unagi build is a debug build. It > generates so much spam that I have to locally patch my tree to comment out > the line that generates the warning, otherwise my logs are essentially > useless. We would only get the warnings with a debug build. I tried to get around that with printfs in a build I used. It is possible that there is some other effect of being debug which contributes to this.

A bit more digging and it turns out that this is caused by the more sophisticated checking we do for whether we need to observe the refresh driver in bug 878142. What happens is, our animation finishes and all ElementAnimations' mNeedsRefreshes are false, so we remove ourselves from the refresh driver. That means we no longer get WillRefresh called and so we never call EnsureStyleRuleFor. That means we no longer set mStyleRuleRefreshTime and so in the warning in GetAnimationRule we think we are out of date. I guess strictly speaking we are, but we are guarenteed that calling EnsureStyleRuleFor would do nothing, so we are not wrong.

Comment on attachment 802783 [details] [diff] [review] third fix lucky r=dbaron

And thanks for putting up with all the iterations here.

And with this patch applied, I observed no occurrences of the message - Yeaaaah