Closed Bug 1151276 Opened 10 years ago Closed 10 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: 10 years ago
Resolution: --- → DUPLICATE
another possible dupe : bug 1134976
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: