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

Status: RESOLVED DUPLICATE of bug 1150127

(Core :: XPCOM, defect)

Description

[Andreas Gal :gal]

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.

Comment 1

[Andreas Gal :gal]

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)

Comment 2

[Andreas Gal :gal]

The entire browsers is taking 2-3s pauses all the time, not just video.

Comment 3

[Andreas Gal :gal]

Attachment: ccpause.jpg

Comment 4

[Andrew McCreight [:mccr8]]

What does the browser console say for CC and GC if you set javascript.options.mem.log to true in about:config?

Comment 5

[Andrew McCreight [:mccr8]]

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)

Comment 6

[Andreas Gal :gal]

I closed most of my tabs except for gmail and facebook. Pauses unchanged.

Comment 7

[Andreas Gal :gal]

I have observed this problem for several months. This is not recent.

Comment 8

[Andreas Gal :gal]

I am seeing 28 ghost windows. I have e10s enabled.

Comment 9

[Andreas Gal :gal]

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

Comment 10

[Andrew McCreight [:mccr8]]

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.

Comment 11

[Andreas Gal :gal]

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

Comment 12

[Andreas Gal :gal]

Anything you need me to do here? Anything else you need or can I close the browser? Happy to dig further.

Comment 13

[Andrew McCreight [:mccr8]]

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

Comment 14

[Andreas Gal :gal]

After closing a bunch of tabs I have 186 ghost windows now.

Comment 15

[Andreas Gal :gal]

Cool. dup it for now I would say and please cc me.

Comment 16

[Andrew McCreight [:mccr8]]

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.

Comment 18

[Mayank Bansal]

another possible dupe : bug 1134976