Closed Bug 1084672 Opened 5 years ago Closed 5 years ago

Slice 1 of a GC lasts 40ms with asm.js game

Categories

(Core :: JavaScript: GC, defect)

defect
Not set

Tracking

()

RESOLVED FIXED
mozilla36
Tracking Status
firefox33 --- wontfix
firefox34 --- fixed
firefox35 --- fixed
firefox36 --- fixed
firefox-esr31 --- affected

People

(Reporter: mccr8, Assigned: roc)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 3 obsolete files)

With the Humble Bundle asm.js games, I'm seeing 4-slice GCs that look like this:

    Slice: 0, Pause: 11.2 (When: 0.0ms, Reason: CC_WAITING): Mark Discard Code: 1.2ms, Mark: 9.0ms, Mark Roots: 6.3ms
    Slice: 1, Pause: 40.3 (When: 111.2ms, Reason: INTER_SLICE_GC): Mark: 40.2ms
    Slice: 2, Pause: 22.4 (When: 252.5ms, Reason: INTER_SLICE_GC): Mark: 22.1ms
    Slice: 3, Pause: 20.5 (When: 377.7ms, Reason: INTER_SLICE_GC): Sweep: 19.6ms, [etc]

Slice 1 is just regular marking, so the GC should be detecting that we're running a game and reduce the slice time.
I looked at this with Andrew and the problem is that the GC no longer gets calls to its NotifyDidPaint code here:
http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.cpp#8479
That's happening in PresShell::DidPaintWindow(), which seems not be called with OMTC enabled. As a consequence, the GC assumes we're not doing much drawing, so it runs longer slices.

Rob, Matt, what can we do about this? Can we run this code from the refresh driver or something?
Flags: needinfo?(roc)
Flags: needinfo?(matt.woodrow)
Not to distract from the bug at hand, but do we really need to allow 40ms slices during normal browsing? Even if we're not painting much, it seems like that could impact responsiveness (e.g. if we happen to be inside a long slice when the user triggers more painting).
It's commonly accepted that anything under 100ms will seem "instantaneous" to users, so we still have 60ms to respond to the user's action. Having longer slices means that we collect more garbage and finish the GC more quickly.
I suggest moving it to the end of nsRefreshDriver::Tick.
Flags: needinfo?(roc)
Duplicate of this bug: 1085466
Attached patch notifydidpaint_from_omtc-v0.diff (obsolete) — Splinter Review
This appears to get us back our 10ms GC slices with the expected reason.
Assignee: nobody → terrence
Status: NEW → ASSIGNED
Attachment #8508314 - Flags: review?(roc)
Comment on attachment 8508314 [details] [diff] [review]
notifydidpaint_from_omtc-v0.diff

Review of attachment 8508314 [details] [diff] [review]:
-----------------------------------------------------------------

I would prefer that you simply move the nsContentUtils::XPConnect()->NotifyDidPaint() call from PresShell::DidPaintWindow to here. A little simpler and safer.
Attachment #8508314 - Flags: review?(roc) → review-
Attached patch notifydidpaint_from_omtc-v1.diff (obsolete) — Splinter Review
Like this? Or did you mean really just move it? Sorry, it's not clear where the other rendering paths are, much less if they all go through here. :-/
Attachment #8508314 - Attachment is obsolete: true
Attachment #8508753 - Flags: review?(roc)
Attached patch fix (obsolete) — Splinter Review
We really should just move it :-)
Assignee: terrence → roc
Attachment #8508753 - Attachment is obsolete: true
Attachment #8508753 - Flags: review?(roc)
Attachment #8509148 - Flags: review?(matt.woodrow)
Comment on attachment 8509148 [details] [diff] [review]
fix

Review of attachment 8509148 [details] [diff] [review]:
-----------------------------------------------------------------

::: layout/base/nsRefreshDriver.cpp
@@ +1368,5 @@
>      mPostRefreshObservers[i]->DidRefresh();
>    }
>  
> +  if (nsContentUtils::XPConnect()) {
> +    nsContentUtils::XPConnect()->NotifyDidPaint();

Should we only do this if we actually painted during this tick?

The above scope, ending with profiler_tracing("Paint... would do that.
Does the patch work correctly everywhere, even with OMTC disabled?
Though, perhaps PresShell::DidPaintWindow() calls without RefreshDriver tick are rare enough that we don't really care.
With the patch, fixed per comment 10, I see 10-15ms max GC pauses in humble bundle games.
Kind patch-update-ask-review-land ping.
(I think we should take the patch to branches, so landing sooner than later is better.)
Flags: needinfo?(roc)
Attached patch fix v2Splinter Review
Flags: needinfo?(roc)
Attachment #8514943 - Flags: review?(matt.woodrow)
Attachment #8509148 - Attachment is obsolete: true
Attachment #8509148 - Flags: review?(matt.woodrow)
Attachment #8514943 - Flags: review?(matt.woodrow) → review+
(In reply to Bill McCloskey (:billm) from comment #3)
> It's commonly accepted that anything under 100ms will seem "instantaneous"
> to users, so we still have 60ms to respond to the user's action. Having
> longer slices means that we collect more garbage and finish the GC more
> quickly.

This is possibly a valid assumption when the user expects a single state change, but is completely invalid with any kind of animation.

Today, regardless of gaming, when many things on the web flows smoothly from here to there (even on Mozilla's front pages), 100, 60, or even 20ms _should_ be unacceptable.
(In reply to Avi Halachmi (:avih) from comment #16)
> This is possibly a valid assumption when the user expects a single state
> change, but is completely invalid with any kind of animation.
> 
> Today, regardless of gaming, when many things on the web flows smoothly from
> here to there (even on Mozilla's front pages), 100, 60, or even 20ms
> _should_ be unacceptable.

I think we agree. The purpose of the code here is to detect when we're animating so that we use a 10ms GC slice instead of a 40ms one. 10ms is still long for animations, but it's the best we can do with our current GC.
By the way, isn't OMTC disabled on ESR31? So I don't think it's affected. I assume this is wontfix for Firefox 33, but it would be nice to get it on 34 and 35 once the fix is confirmed to work.
I thought OSX has OMTC enabled even in 31.
Oh, you may be right. I guess I have Windows on the brain because of all the bugs that cropped up on release.
https://hg.mozilla.org/mozilla-central/rev/12a4c982313f
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla36
Can we get this on Aurora and maybe Beta? We're pretty late for the latter, but the fix is pretty tiny.
Flags: needinfo?(roc)
Comment on attachment 8514943 [details] [diff] [review]
fix v2

Approval Request Comment
[Feature/regressing bug #]: not sure... probably just turning on OMTC
[User impact if declined]: jerky responsiveness during games etc
[Describe test coverage new/current, TBPL]: nothing specific but this code gets hit all the time
[Risks and why]: very low risk, just a tweak to heuristics
[String/UUID change made/needed]: none
Flags: needinfo?(roc)
Flags: needinfo?(matt.woodrow)
Attachment #8514943 - Flags: approval-mozilla-beta?
Attachment #8514943 - Flags: approval-mozilla-aurora?
Comment on attachment 8514943 [details] [diff] [review]
fix v2

Beta+
Aurora+
Attachment #8514943 - Flags: approval-mozilla-beta?
Attachment #8514943 - Flags: approval-mozilla-beta+
Attachment #8514943 - Flags: approval-mozilla-aurora?
Attachment #8514943 - Flags: approval-mozilla-aurora+
Looking good. GC_SLICE_MS dropped significantly.
Yes indeed! Median from 41ms down to 13ms and a slice time distribution now clustered around 10ms instead of 40ms.
(In reply to Bill McCloskey (:billm) from comment #1)
> I looked at this with Andrew and the problem is that the GC no longer gets
> calls to its NotifyDidPaint code here:
> http://mxr.mozilla.org/mozilla-central/source/layout/base/nsPresShell.
> cpp#8479
> That's happening in PresShell::DidPaintWindow(), which seems not be called
> with OMTC enabled. As a consequence, the GC assumes we're not doing much
> drawing, so it runs longer slices.
> 
> Rob, Matt, what can we do about this? Can we run this code from the refresh
> driver or something?

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #25)
> Is this wontfix for esr31?

It only manifests when OMTC is enabled, so 31 shouldn't have it.

And indeed, FX31 release has a median of 12 ms: http://mzl.la/1sJPRU0

FX32 release has a median of 13 ms: http://mzl.la/1sJPZCP

Firefox 33 release has a median of 42 ms: http://mzl.la/1sJQcGg

Great catch.
(In reply to Avi Halachmi (:avih) from comment #29)
> ...
> And indeed, FX31 release has a median of 12 ms: http://mzl.la/1sJPRU0
> ...

(In reply to Emanuel Hoogeveen [:ehoogeveen] from comment #20)
> Oh, you may be right. I guess I have Windows on the brain because of all the
> bugs that cropped up on release.

Hmm.. I fell for the same thing. Windows probably has the dominant number of submissions, hence the visible regression when windows got OMTC.
I thought OMTC was enabled in OSX/FF31
And yes, esr31/OSX is affected.
On OSX releases, currently it's 42, and it goes down slightly through releases and it's about 30ms on release 25, and then 12ms for Firefox 24.

So I guess OMTC was turned on for OS X release on 25.
You need to log in before you can comment on or make changes to this bug.