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

Status: RESOLVED FIXED

(Core :: JavaScript: GC, defect)

Description

[Andrew McCreight [:mccr8]]

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.

Comment 1

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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?

Comment 2

[Emanuel Hoogeveen [:ehoogeveen]]

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).

Comment 3

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

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.

Comment 4

[Robert O'Callahan (:roc) (email my personal email if necessary)]

I suggest moving it to the end of nsRefreshDriver::Tick.

Comment 6

[Terrence Cole [:terrence]]

Attachment: notifydidpaint_from_omtc-v0.diff

This appears to get us back our 10ms GC slices with the expected reason.

Comment 7

[Robert O'Callahan (:roc) (email my personal email if necessary)]

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.

Comment 8

[Terrence Cole [:terrence]]

Attachment: notifydidpaint_from_omtc-v1.diff

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. :-/

Comment 9

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: fix

We really should just move it :-)

Comment 10

[Matt Woodrow (:mattwoodrow)]

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.

Comment 11

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

With the patch, fixed per comment 10, I see 10-15ms max GC pauses in humble bundle games.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

Kind patch-update-ask-review-land ping.
(I think we should take the patch to branches, so landing sooner than later is better.)

Comment 14

[Robert O'Callahan (:roc) (email my personal email if necessary)]

Attachment: fix v2

Comment 15

[Robert O'Callahan (:roc) (email my personal email if necessary)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/12a4c982313f

Comment 16

[Avi Halachmi (:avih)]

(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.

Comment 17

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

(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.

Comment 18

[Emanuel Hoogeveen [:ehoogeveen]]

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.

Comment 19

[Olli Pettay [:smaug][[e-mail]]]

I thought OSX has OMTC enabled even in 31.

Comment 20

[Emanuel Hoogeveen [:ehoogeveen]]

Oh, you may be right. I guess I have Windows on the brain because of all the bugs that cropped up on release.

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/12a4c982313f

Comment 22

[Emanuel Hoogeveen [:ehoogeveen]]

Can we get this on Aurora and maybe Beta? We're pretty late for the latter, but the fix is pretty tiny.

Comment 23

[Robert O'Callahan (:roc) (email my personal email if necessary)]

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

Comment 24

[Lawrence Mandel [:lmandel] (use needinfo)]

Comment on attachment 8514943 [details] [diff] [review]
fix v2

Beta+
Aurora+

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/ab2206155b78
https://hg.mozilla.org/releases/mozilla-beta/rev/2b08e1cb3c6f

Is this wontfix for esr31?

Comment 26

[Roberto Agostino Vitillo (:rvitillo)]

Our alerting system seem to have caught the changes due to this patch: http://alerts.telemetry.mozilla.org/index.html#/detectors/1/alerts/?from=2014-11-06&to=2014-11-06&metrics-filter=

Comment 27

[Olli Pettay [:smaug][[e-mail]]]

Looking good. GC_SLICE_MS dropped significantly.

Comment 28

[Terrence Cole [:terrence]]

Yes indeed! Median from 41ms down to 13ms and a slice time distribution now clustered around 10ms instead of 40ms.

Comment 29

[Avi Halachmi (:avih)]

(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.

Comment 30

[Avi Halachmi (:avih)]

(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.

Comment 31

[Olli Pettay [:smaug][[e-mail]]]

I thought OMTC was enabled in OSX/FF31

Comment 32

[Olli Pettay [:smaug][[e-mail]]]

And yes, esr31/OSX is affected.

Comment 33

[Avi Halachmi (:avih)]

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.