5+ second pause from GC in this jsbin using webcomponents polyfill




JavaScript: GC
2 years ago
2 years ago


(Reporter: bkelly, Unassigned)


(Depends on: 1 bug)

48 Branch

Firefox Tracking Flags

(Not tracked)



(3 attachments)

Created attachment 8754146 [details]
Screenshot 2016-05-18 20.44.38.png


1) Open https://jsbin.com/yutejevobi/2/edit?html,output
2) Open devtools
3) Start a performance trace
4) Click the jsbin "Run with JS" button
5) Notice huge pause
6) After it renders the output, stop the performance trace
7) Observe that we've spent 80% of the time in GC.  In my case this was 9.5 seconds.  See attached screenshot.

Its possible this is something terrible the polyfill is doing, but its an insanely large amount of GC for such a small demo.
I was running on FF46.  The browser also felt sluggish until I shut that tab.

Comment 2

2 years ago
I’d just like to stress (in case it’s not obvious) that this seems to be an issue with Firefox DevTools, specifically how it interacts with the webcomponents polyfill.

Here’s a clean version of the demo (for easier debugging): https://output.jsbin.com/sicova/quiet

For me (Firefox stable/Windows 10), the demo performs without issues, as long as DevTools is not open.
Nick, maybe you can take a look, as this affects both devtools and GC?
Flags: needinfo?(nfitzgerald)
Created attachment 8754407 [details]
devtools profile

I'm seeing a huge series of 10ms incremental slices because of either CC_WAITING or CC_FORCED (we display both reasons as "Forced by the Cycle Collector" in the UI) followed by 10ms nursery collections because of REFRESH_FRAME. 10ms nursery collections are usually not a good thing, especially when happening repeatedly...

After that, I see a ton of 5ms nursery collections because of EVICT_NURSERY.

Overall, I'm confused why we are seeing SO MUCH nursery action here and no major GC slices at all. This sounds frighteningly similar to bug 1233857...
Flags: needinfo?(nfitzgerald)
Created attachment 8754410 [details]
screenshot of top of call tree

About half of our total time is spent in nursery collections, and about half of those collections are happening under the refresh driver. Matches with the REFRESH_FRAME minor gc reasons. Why each nursery collection is taking 10ms will require profiling with JS_GC_PROFILE_NURSERY.

About 15% of the other half of nursery collections are under the webcomponents' JS, so I'm going to just assume those aren't an issue for now.

The remaining 10% of nursery collections are happening under the devtools' debugger's ThreadActor code. Not good, but not surprising, as this code has historically been problematic performance-wise. As has been suggested before, I think we need to turn the debugger off while profiling. Now if we could just find time to do it...
An additional 14% of time in JS_IterateCompartments is reported as "GC", but is used by the debugger to iterate JSScripts in the debuggees. So thats about 25% of time altogether caused just by the debugger being always on.
So in summary, we seem to have two issues here:

1. The debugger is always on, and is not cheap, so it is affecting performance and skewing any profiles taken.

2. There is a weird nursery cliff involving 5-10ms nursery collections(!) and possibly the refresh driver.
(In reply to Šime Vidas from comment #2)
> Here’s a clean version of the demo (for easier debugging):
> https://output.jsbin.com/sicova/quiet

Thanks for splitting this out, but a note for others reproducing: I am able to reproduce more of an issue by using the original testcase and the "run with js" button than with this link. I can repro with this link too, but the symptoms are less extreme.
You need to log in before you can comment on or make changes to this bug.