Closed Bug 1151276 Opened 6 years ago Closed 6 years ago

Cycle collection is causing 2s pauses in video every few seconds

Categories

(Core :: XPCOM, defect)

Product:
Core
Component:
XPCOM
Platform:
x86
macOS
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED DUPLICATE of bug 1150127
Tracking Flags:
Tracking Status
firefox40 --- affected

People

(Reporter: gal, Unassigned)

Details

Attachments

(1 file)

ccpause.jpg
812.09 KB, image/jpeg
Details 
I was finally able to reproduce this. I frequently see massive video lag every few seconds. Looks like the cycle collector is taking ages to collect. I will attach some logs and a video. This could be responsible for a lot of our flash problems, indirectly.
I usually get this after having Firefox in use for a while. I use gmail and google docs heavily and I have a hunch they are involved. I will try to diagnose some more (close tabs etc) in a second.

Running Time	Self		Symbol Name
32906.0ms   96.7%	0.0	 	Main Thread  0xfcf46
32754.0ms   96.3%	0.0	 	 start
32754.0ms   96.3%	0.0	 	  main
32754.0ms   96.3%	0.0	 	   XRE_InitChildProcess
32754.0ms   96.3%	0.0	 	    MessageLoop::Run()
32754.0ms   96.3%	0.0	 	     XRE_RunAppShell
32754.0ms   96.3%	0.0	 	      nsAppShell::Run()
32753.0ms   96.3%	3.0	 	       -[NSApplication run]
32572.0ms   95.8%	3.0	 	        -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
32561.0ms   95.7%	4.0	 	         -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:]
32476.0ms   95.5%	11.0	 	          _DPSNextEvent
32397.0ms   95.2%	0.0	 	           _BlockUntilNextEventMatchingListInModeWithFilter
32396.0ms   95.2%	0.0	 	            ReceiveNextEventCommon
32369.0ms   95.2%	6.0	 	             RunCurrentEventLoopInMode
32338.0ms   95.1%	4.0	 	              CFRunLoopRunSpecific
32275.0ms   94.9%	12.0	 	               __CFRunLoopRun
31851.0ms   93.6%	4.0	 	                __CFRunLoopDoSources0
31819.0ms   93.5%	0.0	 	                 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__
31818.0ms   93.5%	5.0	 	                  nsAppShell::ProcessGeckoEvents(void*)
31600.0ms   92.9%	2.0	 	                   nsBaseAppShell::NativeEventCallback()
31584.0ms   92.9%	0.0	 	                    NS_ProcessPendingEvents(nsIThread*, unsigned int)
31577.0ms   92.8%	12.0	 	                     nsThread::ProcessNextEvent(bool, bool*)
19195.0ms   56.4%	0.0	 	                      nsTimerEvent::Run()
19194.0ms   56.4%	0.0	 	                       nsTimerImpl::Fire()
18698.0ms   54.9%	0.0	 	                        nsJSContext::RunCycleCollectorSlice()
18698.0ms   54.9%	0.0	 	                         nsCycleCollector_collectSlice(js::SliceBudget&, bool)
18698.0ms   54.9%	0.0	 	                          nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool)
16614.0ms   48.8%	0.0	 	                           nsCycleCollector::MarkRoots(js::SliceBudget&)
16611.0ms   48.8%	76.0	 	                            CCGraphBuilder::BuildGraph(js::SliceBudget&)
3.0ms    0.0%	0.0	 	                            <Unknown Address>
1563.0ms    4.5%	49.0	 	                           nsCycleCollector::ScanRoots(bool)
1195.0ms    3.5%	45.0	 	                            nsCycleCollector::ScanBlackNodes()
317.0ms    0.9%	211.0	 	                            nsCycleCollector::ScanIncrementalRoots()
2.0ms    0.0%	0.0	 	                            nsCycleCollector::ScanWeakMaps()
480.0ms    1.4%	2.0	 	                           nsCycleCollector::CleanupAfterCollection()
30.0ms    0.0%	30.0	 	                           nsCycleCollector::CollectWhite()
11.0ms    0.0%	9.0	 	                           nsCycleCollector::FreeSnowWhite(bool)
The entire browsers is taking 2-3s pauses all the time, not just video.
Component: XPConnect → XPCOM
Attached image ccpause.jpg — 
What does the browser console say for CC and GC if you set javascript.options.mem.log to true in about:config?
Also, in about:memory, if you do "measure" do you see anything under ghost-windows?  If you have e10s enabled, you'll have to look through all of the entries.  I ask because this sounds like an issue I'm seeing that started recently where we start leaking windows, which makes the CC take forever. (bug 1150127)
I closed most of my tabs except for gmail and facebook. Pauses unchanged.
I have observed this problem for several months. This is not recent.
I am seeing 28 ghost windows. I have e10s enabled.
CC(T+115313.9) max pause: 5ms, total time: 27ms, slices: 6, suspected: 2742, visited: 5683 RCed and 20042 GCed, collected: 5084 RCed and 19642 GCed (19642|0|7 waiting for GC)
ForgetSkippable 8 times before CC, min: 0 ms, max: 5 ms, avg: 2 ms, total: 19 ms, max sync: 0 ms, removed: 7016
CC(T+115316.2) max pause: 2527ms, total time: 2841ms, slices: 50, suspected: 182, visited: 436651 RCed and 2216894 GCed, collected: 4 RCed and 7 GCed (7|0|0 waiting for GC)
ForgetSkippable 7 times before CC, min: 0 ms, max: 16 ms, avg: 3 ms, total: 22 ms, max sync: 0 ms, removed: 74
Yeah, the ghost windows are almost certainly responsible for the huge CC times.  Ghost windows are not being displayed, so we can't optimize them out of the CC graph, so CC times get terrible.
CC(T+115313.9) max pause: 5ms, total time: 27ms, slices: 6, suspected: 2742, visited: 5683 RCed and 20042 GCed, collected: 5084 RCed and 19642 GCed (19642|0|7 waiting for GC)
ForgetSkippable 8 times before CC, min: 0 ms, max: 5 ms, avg: 2 ms, total: 19 ms, max sync: 0 ms, removed: 7016
CC(T+115316.2) max pause: 2527ms, total time: 2841ms, slices: 50, suspected: 182, visited: 436651 RCed and 2216894 GCed, collected: 4 RCed and 7 GCed (7|0|0 waiting for GC)
ForgetSkippable 7 times before CC, min: 0 ms, max: 16 ms, avg: 3 ms, total: 22 ms, max sync: 0 ms, removed: 74
Anything you need me to do here? Anything else you need or can I close the browser? Happy to dig further.
(In reply to Andreas Gal :gal from comment #12)
> Anything you need me to do here? Anything else you need or can I close the
> browser? Happy to dig further.

This sounds like the same problem I'm seeing, aside from the recentness, so I think there's nothing more I need from you at this point.  (I have a bunch of leaking windows in this very browser session.)
After closing a bunch of tabs I have 186 ghost windows now.
Cool. dup it for now I would say and please cc me.
If you have some ideas how to get it to reproduce that could be useful.  I haven't been able to reproduce in a clean profile yet, only in my regular browser session.
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1150127
another possible dupe : bug 1134976
You need to log in before you can comment on or make changes to this bug.