Closed Bug 1122196 Opened 7 years ago Closed 7 years ago

GCs taking 200ms

Categories

(Core :: JavaScript: GC, defect)

35 Branch
x86_64
Windows 7
defect
Not set
normal

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: vladan, Unassigned)

References

(Blocks 1 open bug)

Details

Attachments

(1 file)

Attached file 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
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.
Blocks: 650161
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.
Also this build does not have compacting, so that is not implicated either.
No longer blocks: 650161
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.
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.
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?
Flags: needinfo?(vdjeric)
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
Flags: needinfo?(vdjeric)
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?
(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.
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.
Please re-open if you find a way to reproduce.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.