1122196 - GCs taking 200ms

Status: RESOLVED INCOMPLETE

(Core :: JavaScript: GC, defect)

Description

[Vladan Djeric (:vladan)]

Attachment: looong gcs.txt

I noticed my Firefox being very sluggish even though system load was low. I'm using Firefox 35.0 (release-channel) on this profile, with 4 windows and about a dozen tabs per window. 

I captured a profile that showed frequent GCs lasting up to 200ms

Profile: http://people.mozilla.org/~bgirard/cleopatra/#report=ca5d4d4e4e242fcf8d1d90eeee9ccc068504166b&selection=0,1,82

See attachment for log of GCs

Comment 1

[Terrence Cole [:terrence]]

Turns out my own profile was reproducing this. The cause is a bunch of things, but most proximately on Compacting GC, in particular: https://hg.mozilla.org/mozilla-central/rev/d63a5fe3ace7

So what's going on here is that (at least on my profile) we're spending 700ms of a 900ms GC in callWeakPointerCallbacks, generally split into 90-100ms chunks at the start of each zone-group. If I replace the JS_UpdateWeakPointerAfterMovingGCUnbarriered call with an inline isMarked check (using the ::details in HeapAPI.h), this drops to 35ms of a 300ms GC.

Of course, this "solution" crashes very quickly because it fails for allocatedDuringIncremental, compacting, etc, but before it crashes it does clearly show that the indirection and general heaviness of IsAboutToBeFinalized is to blame for the perf issue.

Comment 2

[Terrence Cole [:terrence]]

Actually, I'm wrong, --enable-shared-js doesn't even work anymore, so it's probably not the call overhead. Specifically, I get identical perf as above if I replace JS_UpdateWeakPointerAfterGCUnbarriered with:
    if (!(*objp)->asTenured().isMarked())
        *objp = nullptr;

So it's one of the other checks in IsAboutToBeFinalized that's taking too much time. Note: this is all --disable-debug builds.

Comment 3

[Terrence Cole [:terrence]]

Also this build does not have compacting, so that is not implicated either.

Comment 4

[Terrence Cole [:terrence]]

Adding a specialization for IsAboutToBeFinalized<JSObject> that skips the IsPermanentAtom check moves the needle to 90/350ms, which is pretty livable. Unfortunately, I'm still crashing almost immediately with that patch. I'll investigate more when I'm fresh tomorrow morning.

Comment 5

[Jon Coppeard (:jonco)]

Weird.  The IsPermanentAtom check should be optimised out because the specialisation of ThingIsPermanentAtom() for JSObject* just returns false.

On another note, we could try and split up the weak pointer updates by zone group rather than doing them all for every zone group, but I'm not sure whether the rest of the system has the necessary information to do this at present.

Comment 6

[Terrence Cole [:terrence]]

Andrew helped me dive into the CC logs to find out why sort of things are in that dictionary. It seems that the majority of them are simple event listeners. The DOM interface to these has been converted to bindings, so the only reasonable way we can fill this map up now is via an extension. After a bit of poking, I disabled PrivacyBadger. With PrivacyBadger disabled, my GC times dropped from 1200ms to 60ms.

Vladan, do you have PrivacyBadger enabled?

Comment 7

[Vladan Djeric (:vladan)]

No, I don't have Privacy Badger. 

I have Adblock Plus, Gecko Profiler, MemChaser and "about:addons-memory".

I closed tabs & disabled extensions one-by-one. Disabling the extensions did not result in any significant improvements: https://etherpad.mozilla.org/xeYha4BNpB

Comment 8

[Terrence Cole [:terrence]]

After "close twitter pinned tab" your GC max-pause times appear to be generally hitting the normal target of 40ms. Could you see if the problem reproduces if you open a tab with twitter?

Comment 9

[Vladan Djeric (:vladan)]

(In reply to Terrence Cole [:terrence] from comment #8)
> After "close twitter pinned tab" your GC max-pause times appear to be
> generally hitting the normal target of 40ms. Could you see if the problem
> reproduces if you open a tab with twitter?

I've had trouble reproducing this behavior on the latest Nightlies. With only GMail and Google Calendar tabs pinned, I get 40ms max-pause times. With Twitter pinned as well, the max pause times are only slightly higher 41-46ms.
I had the Gecko profiler and Pocket extensions installed for this latest experiment.

I'll keep an eye out.

Comment 10

[Steve Fink [:sfink] [:s:]]

If you have a chance, you could check if it still reproduces for you on an older Nightly, to see if it was fixed by a change on their side.

Comment 11

[Terrence Cole [:terrence]]

Please re-open if you find a way to reproduce.