improve cycle collector performance

RESOLVED FIXED

Status

()

Core
XPCOM
RESOLVED FIXED
8 years ago
5 years ago

People

(Reporter: gal, Unassigned)

Tracking

(Blocks: 1 bug)

Trunk
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(Not tracked)

Details

Comment hidden (empty)
(Reporter)

Comment 1

8 years ago
In a browser with a single gmail window open I see a cycle collection every 5 seconds or so. It usually takes about 60ms (this is a 2GHz x86 laptop, fennec devices must get completely hammered by this).

js_IsAboutToBeFinalized seems to be an obvious turd we should fix right away.

# Report 1 - Session 6 - Time Profile of Everything <CycleCollection>
SharkProfileViewer
# Generated from the visible portion of the outline view
- 12.8%, js_GC, libmozjs.dylib
- 7.6%, js_SweepScopeProperties, libmozjs.dylib
- 6.3%, js_IsAboutToBeFinalized, libmozjs.dylib
- 5.8%, PL_DHashTableOperate, XUL
- 5.4%, JS_DHashTableEnumerate, libmozjs.dylib
- 4.2%, js_CallGCMarker, libmozjs.dylib
- 4.2%, WrappedNativeMarker(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 3.3%, nsXPConnect::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 2.8%, nsDeque::Push(void*), XUL
- 2.8%, GraphWalker<ScanBlackVisitor>::DoWalk(nsDeque&), XUL
- 2.8%, WrappedNativeSuspecter(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 2.6%, GCGraphBuilder::NoteXPCOMChild(nsISupports*), XUL
- 2.6%, js_TraceObject, libmozjs.dylib
- 2.0%, GCGraphBuilder::NoteScriptChild(unsigned int, void*), XUL
- 1.8%, JSFreePointerListTask::run(), libmozjs.dylib
- 1.5%, nsDeque::PopFront(), XUL
- 1.5%, PL_DHashTableFinish, XUL
- 1.3%, js_atom_sweeper(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), libmozjs.dylib
- 1.3%, WrappedNativeJSGCThingTracer(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 1.1%, nsGenericElement::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 1.1%, JS_TraceChildren, libmozjs.dylib
- 1.1%, js_TraceScript, libmozjs.dylib
- 1.0%, JSScopeProperty::trace(JSTracer*), libmozjs.dylib
- 1.0%, WrappedNativeTearoffSweeper(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.9%, PL_DHashTableInit, XUL
+ 0.8%, PtrToNodeMatchEntry(PLDHashTable*, PLDHashEntryHdr const*, void const*), XUL
| + 0.8%, PL_DHashTableOperate, XUL
| | + 0.4%, GCGraphBuilder::NoteScriptChild(unsigned int, void*), XUL
| | | + 0.2%, js_CallGCMarker, libmozjs.dylib
| | | | + 0.2%, js_TraceObject, libmozjs.dylib
| | | | | + 0.2%, nsXPConnect::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
| | | | | | + 0.2%, nsCycleCollector::BeginCollection(), XUL
| | | | | | | + 0.2%, XPCCycleCollectGCCallback(JSContext*, JSGCStatus), XUL
| | | | | | | | + 0.2%, js_GC, libmozjs.dylib
| | | | | | | | | + 0.2%, nsXPConnect::Collect(), XUL
| | | | | | | | | | + 0.2%, nsCycleCollector::Collect(unsigned int), XUL
| | | | | | | | | | | + 0.2%, nsJSContext::MaybeCC(int), XUL
| | | | | | | | | | | | + 0.2%, nsXMLHttpRequest::RequestCompleted(), XUL
| | | | | | | | | | | | | + 0.2%, nsXMLHttpRequest::OnStopRequest(nsIRequest*, nsISupports*, unsigned int), XUL
| | | | | | | | | | | | | | + 0.2%, nsHttpChannel::OnStopRequest(nsIRequest*, nsISupports*, unsigned int), XUL
| | | | | | | | | | | | | | | + 0.2%, nsInputStreamPump::OnStateStop(), XUL
| | | | | | | | | | | | | | | | + 0.2%, nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*), XUL
| | | | | | | | | | | | | | | | | + 0.2%, nsInputStreamReadyEvent::Run(), XUL
| | | | | | | | | | | | | | | | | | + 0.2%, nsThread::ProcessNextEvent(int, int*), XUL
| | | | | | | | | | | | | | | | | | | + 0.2%, NS_ProcessPendingEvents_P(nsIThread*, unsigned int), XUL
| | | | | | | | | | | | | | | | | | | | + 0.2%, nsBaseAppShell::NativeEventCallback(), XUL
| | | | | | | | | | | | | | | | | | | | | + 0.2%, nsAppShell::ProcessGeckoEvents(void*), XUL
| | | | | | | | | | | | | | | | | | | | | | + 0.2%, nsAppShell::Run(), XUL
| | | | | | | | | | | | | | | | | | | | | | | + 0.2%, nsAppStartup::Run(), XUL
| | | | | | | | | | | | | | | | | | | | | | | | + 0.2%, XRE_main, XUL
| | | | | | | | | | | | | | | | | | | | | | | | |   0.2%, main, firefox-bin
| | | - 0.2%, nsGenericElement::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
| | - 0.3%, GCGraphBuilder::NoteXPCOMChild(nsISupports*), XUL
| | - 0.1%, nsPurpleBuffer::SelectPointers(GCGraphBuilder&), XUL
- 0.8%, NS_TableDrivenQI(void*, QITableEntry const*, nsID const&, void**), XUL
- 0.8%, js_GetGCThingTraceKind, libmozjs.dylib
- 0.8%, PR_Lock, libnspr4.dylib
- 0.7%, nsJSEventListener::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.6%, nsCycleCollector::BeginCollection(), XUL
- 0.6%, GCGraphBuilder::NoteXPCOMRoot(nsISupports*), XUL
- 0.5%, NS_CycleCollectorSuspect2_P, XUL
- 0.5%, nsGenericElement::AddRef(), XUL
- 0.5%, fun_trace(JSTracer*, JSObject*), libmozjs.dylib
- 0.5%, nsJSEventListener::cycleCollection::Trace(void*, void (*)(unsigned int, void*, void*), void*), XUL
- 0.5%, nsDeque::~nsDeque(), XUL
- 0.5%, WrappedNativeProtoMarker(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.5%, NoteJSChild(JSTracer*, void*, unsigned int), XUL
- 0.5%, GraphWalker<scanVisitor>::DoWalk(nsDeque&), XUL
- 0.4%, PL_DHashTableEnumerate, XUL
- 0.4%, nsPurpleBuffer::SelectPointers(GCGraphBuilder&), XUL
- 0.4%, nsXBLProtoImpl::Trace(void (*)(unsigned int, void*, void*), void*) const, XUL
- 0.4%, NativeInterfaceGC(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.3%, nsAttrAndChildArray::AttrCount() const, XUL
- 0.3%, nsXULPrototypeNode::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.3%, PL_DHashVoidPtrKeyStub, XUL
- 0.3%, nsGenericElement::cycleCollection::Trace(void*, void (*)(unsigned int, void*, void*), void*), XUL
- 0.3%, nsDeque::GrowCapacity(), XUL
- 0.3%, XPCWrappedNative::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.3%, JS_CallTracer, libmozjs.dylib
- 0.3%, XPCWrappedNativeScope::MarkAllWrappedNativesAndProtos(), XUL
- 0.3%, PL_DHashClearEntryStub, XUL
- 0.2%, JS_DHashTableOperate, libmozjs.dylib
- 0.2%, js_script_filename_sweeper(JSHashEntry*, int, void*), libmozjs.dylib
- 0.2%, nsDocument::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.2%, nsGenericElement::Release(), XUL
- 0.2%, nsGenericDOMDataNode::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.2%, GCGraphBuilder::NoteNativeChild(void*, nsCycleCollectionParticipant*), XUL
- 0.2%, nsXBLInsertionPoint::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.2%, PR_EnterMonitor, libnspr4.dylib
- 0.2%, nsJSContext::QueryInterface(nsID const&, void**), XUL
- 0.2%, nsNodeInfo::AddRef(), XUL
- 0.2%, nsNodeInfo::QueryInterface(nsID const&, void**), XUL
- 0.2%, XPCJSRuntime::TraceXPConnectRoots(JSTracer*, int), XUL
- 0.2%, xpc_TraceForValidWrapper(JSTracer*, XPCWrappedNative*), XUL
- 0.2%, XPCWrappedNative::GetWrappedNativeOfJSObject(JSContext*, JSObject*, JSObject*, JSObject**, XPCWrappedNativeTearOff**), XUL
- 0.2%, nsCycleCollector::RootWhite(), XUL
- 0.2%, PR_Unlock, libnspr4.dylib
- 0.2%, nsXPCWrappedJS::AddRef(), XUL
- 0.1%, nsScriptObjectTracer::TraverseScriptObjects(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, nsXBLProtoImplProperty::Trace(void (*)(unsigned int, void*, void*), void*) const, XUL
- 0.1%, XPCWrappedNative::TraceOtherWrapper(JSTracer*), XUL
- 0.1%, nsCycleCollector_finishCollection(), XUL
- 0.1%, _PR_UNIX_GetInterval, libnspr4.dylib
- 0.1%, NativeInterfaceSweeper(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.1%, nsBaseCommandController::QueryInterface(nsID const&, void**), XUL
- 0.1%, nsSmallVoidArray::Count() const, XUL
- 0.1%, array_trace(JSTracer*, JSObject*), libmozjs.dylib
- 0.1%, InMemoryDataSource::Internal::Release(), XUL
- 0.1%, nsXBLPrototypeBinding::Traverse(nsCycleCollectionTraversalCallback&) const, XUL
- 0.1%, nsBindingManager::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, nsXBLDocumentInfo::AddRef(), XUL
- 0.1%, nsTHashtable<nsBaseHashtableET<nsISupportsHashKey, nsRefPtr<nsXBLBinding> > >::s_HashKey(PLDHashTable*, void const*), XUL
- 0.1%, nsEventListenerManager::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, js_FinishTitle, libmozjs.dylib
- 0.1%, JS_IsAboutToBeFinalized, libmozjs.dylib
- 0.1%, XPCVariant::Release(), XUL
- 0.1%, nsGlobalChromeWindow::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, nsXBLProtoImplMethod::Trace(void (*)(unsigned int, void*, void*), void*) const, XUL
- 0.1%, nsCOMPtr_base::begin_assignment(), XUL
- 0.1%, nsXMLElement::QueryInterface(nsID const&, void**), XUL
- 0.1%, nsXPathEvaluator::AggregatedQueryInterface(nsID const&, void**), XUL
- 0.1%, nsDocument::cycleCollection::Trace(void*, void (*)(unsigned int, void*, void*), void*), XUL
- 0.1%, nsHashtable::Enumerate(int (*)(nsHashKey*, void*, void*), void*), XUL
- 0.1%, JSScope::destroy(JSContext*), libmozjs.dylib
- 0.1%, nsGenericDOMDataNode::AddRef(), XUL
- 0.1%, nsXULPrototypeNode::cycleCollection::Trace(void*, void (*)(unsigned int, void*, void*), void*), XUL
- 0.1%, WrappedJSDyingJSObjectFinder(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.1%, TraceJSObject(unsigned int, void*, void*), XUL
- 0.1%, nsJSContext::Release(), XUL
- 0.1%, XPCWrappedNativeScope::SuspectAllWrappers(XPCJSRuntime*, JSContext*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, nsXPCWrappedJS::cycleCollection::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, XPCJSRuntime::GCCallback(JSContext*, JSGCStatus), XUL
- 0.1%, nsCycleCollector::ScanRoots(), XUL
- 0.1%, XPCWrappedNative::Release(), XUL
- 0.1%, nsXPCWrappedJS::TraceJS(JSTracer*), XUL
- 0.1%, NoteJSHolder(JSDHashTable*, JSDHashEntryHdr*, unsigned int, void*), XUL
- 0.1%, nsXBLDocumentInfo::cycleCollection::Trace(void*, void (*)(unsigned int, void*, void*), void*), XUL
- 0.1%, XPCTraceableVariant::TraceJS(JSTracer*), XUL
- 0.1%, JSContextParticipant::Traverse(void*, nsCycleCollectionTraversalCallback&), XUL
- 0.1%, GCGraphBuilder::NoteRoot(unsigned int, void*, nsCycleCollectionParticipant*), XUL
- 0.1%, XPCWrappedNativeScope::TraceJS(JSTracer*, XPCJSRuntime*), XUL
- 0.1%, nsXPCWrappedJS::QueryInterface(nsID const&, void**), XUL
- 0.1%, nsXPConnect::GetRuntimeInstance(), XUL
(Reporter)

Comment 2

8 years ago
gmail open, idle:

#0  nsCycleCollector::BeginCollection (this=0x103859e00) at ../../../xpcom/base/nsCycleCollector.cpp:2581
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
#5  0x00000001005d02f3 in nsJSContext::CC () at /Users/gal/workspace/tracemonkey-repository/dom/base/nsJSEnvironment.cpp:3549
#6  0x00000001005d02f3 in nsJSContext::IntervalCC () at /Users/gal/workspace/tracemonkey-repository/dom/base/nsJSEnvironment.cpp:3637

#0  nsCycleCollector::BeginCollection (this=0x103859e00) at ../../../xpcom/base/nsCycleCollector.cpp:2581
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
#5  0x00000001005d02f3 in nsJSContext::CC () at /Users/gal/workspace/tracemonkey-repository/dom/base/nsJSEnvironment.cpp:3549
#6  0x00000001005d02f3 in nsJSContext::IntervalCC () at /Users/gal/workspace/tracemonkey-repository/dom/base/nsJSEnvironment.cpp:3637
#7  0x00000001005d02f3 in nsUserActivityObserver::Observe (this=0x11bc62c60, aSubject=<value temporarily unavailable, due to optimizations>, aTopic=0x100db0d68 "user-interaction-inactive", aData=<value temporarily unavailable, due to optimizations>) at ../../../dom/base/nsJSEnvironment.cpp:268
The patch in bug 497789 should help js_SweepScopeProperties (renamed to js::SweepScopeProperties) not loom so large.

/be
(Reporter)

Comment 4

8 years ago
Switching to cnn.com and then gmail.com:

#0  nsCycleCollector::BeginCollection (this=0x103859e00) at ../../../xpcom/base/nsCycleCollector.cpp:2581
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
#5  0x00000001005d01bc in nsJSContext::MaybeCC (aHigherProbability=1) at ../../../dom/base/nsJSEnvironment.cpp:3549
#6  0x00000001005d056e in GCTimerFired (aTimer=<value temporarily unavailable, due to optimizations>, aClosure=<value temporarily unavailable, due to optimizations>) at ../../../dom/base/nsJSEnvironment.cpp:3625
#7  0x0000000100b738ba in nsTimerImpl::Fire (this=0x11ac549e0) at ../../../xpcom/threads/nsTimerImpl.cpp:427
#8  0x0000000100b73968 in nsTimerEvent::Run (this=<value temporarily unavailable, due to optimizations>) at ../../../xpcom/threads/nsTimerImpl.cpp:519
#9  0x0000000100b701b3 in nsThread::ProcessNextEvent (this=0x102c01580, mayWait=0, result=0x7fff5fbfd0ec) at ../../../xpcom/threads/nsThread.cpp:527
#10 0x0000000100b31f7e in NS_ProcessPendingEvents_P (thread=0x102c01580, timeout=20) at nsThreadUtils.cpp:200
#11 0x0000000100ae4a06 in nsBaseAppShell::NativeEventCallback (this=0x102c0a600) at ../../../../widget/src/xpwidgets/nsBaseAppShell.cpp:125
#12 0x0000000100ab3cc7 in nsAppShell::ProcessGeckoEvents (aInfo=<value temporarily unavailable, due to optimizations>) at ../../../../widget/src/cocoa/nsAppShell.mm:510
(Reporter)

Comment 5

8 years ago
XML Requests can still trigger GCs it seems:

(gdb) bt 
#0  nsCycleCollector::BeginCollection (this=0x103859e00) at ../../../xpcom/base/nsCycleCollector.cpp:2581
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
#5  0x00000001005d01bc in nsJSContext::MaybeCC (aHigherProbability=0) at ../../../dom/base/nsJSEnvironment.cpp:3549
#6  0x0000000100479371 in ~nsString [inlined] () at ../../../../content/base/src/nsXMLHttpRequest.cpp:2163
#7  0x0000000100479371 in ~nsDependentString [inlined] () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsTDependentString.h:53
#8  0x0000000100479371 in nsXMLHttpRequest::RequestCompleted (this=0x1254f11a0) at ../../../../content/base/src/nsXMLHttpRequest.cpp:2164
#9  0x0000000100479622 in nsXMLHttpRequest::OnStopRequest (this=0x1254f11a0, request=0x1254f3558, ctxt=<value temporarily unavailable, due to optimizations>, status=0) at ../../../../content/base/src/nsXMLHttpRequest.cpp:2106
#10 0x0000000100150816 in nsCOMPtr<nsIStreamListener>::operator= () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsCOMPtr.h:5283
#11 0x0000000100150816 in nsHttpChannel::OnStopRequest (this=0x1254f3510, request=0x0, ctxt=<value temporarily unavailable, due to optimizations>, status=0) at ../../../../../netwerk/protocol/http/src/nsHttpChannel.cpp:5284
#12 0x00000001000c98b7 in nsCOMPtr<nsIStreamListener>::operator= () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsCOMPtr.h:576
#13 0x00000001000c98b7 in nsInputStreamPump::OnStateStop (this=0x1254f4890) at ../../../../netwerk/base/src/nsInputStreamPump.cpp:577
#14 0x00000001000c9f98 in nsInputStreamPump::OnInputStreamReady (this=0x1254f4890, stream=<value temporarily unavailable, due to optimizations>) at ../../../../netwerk/base/src/nsInputStreamPump.cpp:401
#15 0x0000000100b536c4 in nsCOMPtr<nsIInputStreamCallback>::operator= () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsCOMPtr.h:112
#16 0x0000000100b536c4 in nsInputStreamReadyEvent::Run (this=0x1254f4630) at ../../../xpcom/io/nsStreamUtils.cpp:113
#17 0x0000000100b701b3 in nsThread::ProcessNextEvent (this=0x102c01580, mayWait=0, result=0x7fff5fbfd0ec) at ../../../xpcom/threads/nsThread.cpp:527
#18 0x0000000100b31f7e in NS_ProcessPendingEvents_P (thread=0x102c01580, timeout=20) at nsThreadUtils.cpp:200
#19 0x0000000100ae4a06 in nsBaseAppShell::NativeEventCallback (this=0x102c0a600) at ../../../../widget/src/xpwidgets/nsBaseAppShell.cpp:125
#20 0x0000000100ab3cc7 in nsAppShell::ProcessGeckoEvents (aInfo=<value temporarily unavailable, due to optimizations>) at ../../../../widget/src/cocoa/nsAppShell.mm:510
#21 0x00007fff82eb6271 in __CFRunLoopDoSources0 ()
#22 0x00007fff82eb4469 in __CFRunLoopRun ()
#23 0x00007fff82eb3c2f in CFRunLoopRunSpecific ()
#24 0x00007fff8478aa4e in RunCurrentEventLoopInMode ()
#25 0x00007fff8478a853 in ReceiveNextEventCommon ()
#26 0x00007fff8478a70c in BlockUntilNextEventMatchingListInMode ()
#27 0x00007fff87f871f2 in _DPSNextEvent ()
#28 0x00007fff87f86b41 in -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] ()
#29 0x00007fff87f4c747 in -[NSApplication run] ()
#30 0x0000000100ab35bb in nsAppShell::Run (this=<value temporarily unavailable, due to optimizations>) at ../../../../widget/src/cocoa/nsAppShell.mm:863
#31 0x0000000100944a64 in nsAppStartup::Run (this=0x102c41f90) at ../../../../../toolkit/components/startup/src/nsAppStartup.cpp:183
#32 0x0000000100011004 in XRE_main (argc=<value temporarily unavailable, due to optimizations>, argv=<value temporarily unavailable, due to optimizations>, aAppData=<value temporarily unavailable, due to optimizations>) at ../../../toolkit/xre/nsAppRunner.cpp:3489
#33 0x0000000100001a3e in main (argc=1, argv=0x7fff5fbfeb80) at ../../../browser/app/nsBrowserApp.cpp:158
(gdb) up
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
392	            gInCollection = nsCycleCollector_beginCollection();

(gdb) 
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
3169	        (void) rt->gcCallback(cx, JSGC_MARK_END);
(gdb) 
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
479	    JS_GC(cx);
(gdb) up
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
2522	                (mRuntimes[nsIProgrammingLanguage::JAVASCRIPT])->Collect();
(gdb) up
#5  0x00000001005d01bc in nsJSContext::MaybeCC (aHigherProbability=0) at ../../../dom/base/nsJSEnvironment.cpp:3549
3549	  sCollectedObjectsCounts = nsCycleCollector_collect();
(gdb) up
#6  0x0000000100479371 in ~nsString [inlined] () at ../../../../content/base/src/nsXMLHttpRequest.cpp:2163
2163	  nsJSContext::MaybeCC(PR_FALSE);
(gdb) up
#7  0x0000000100479371 in ~nsDependentString [inlined] () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsTDependentString.h:53
2163	  nsJSContext::MaybeCC(PR_FALSE);
(gdb) up
#8  0x0000000100479371 in nsXMLHttpRequest::RequestCompleted (this=0x1254f11a0) at ../../../../content/base/src/nsXMLHttpRequest.cpp:2164
2163	  nsJSContext::MaybeCC(PR_FALSE);
(gdb) list
2159	    // We're a multipart request, so we're not done. Reset to opened.
2160	    ChangeState(XML_HTTP_REQUEST_OPENED);
2161	  }
2162	
2163	  nsJSContext::MaybeCC(PR_FALSE);
2164	  return rv;
2165	}
(Reporter)

Comment 6

8 years ago
Right after (one second or so) I got another one:

(gdb) bt
#0  nsCycleCollector::BeginCollection (this=0x103859e00) at ../../../xpcom/base/nsCycleCollector.cpp:2581
#1  0x00000001000216e9 in XPCCycleCollectGCCallback (cx=0x103267a00, status=JSGC_MARK_END) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:392
#2  0x000000010242bc12 in js_GC (cx=<value temporarily unavailable, due to optimizations>, gckind=GC_NORMAL) at ../../../js/src/jsgc.cpp:3169
#3  0x000000010001e886 in nsXPConnect::Collect (this=0x102c11e50) at ../../../../../js/src/xpconnect/src/nsXPConnect.cpp:479
#4  0x0000000100b7cfb4 in nsCycleCollector::Collect (this=0x103859e00, aTryCollections=1) at ../../../xpcom/base/nsCycleCollector.cpp:2522
#5  0x00000001005d01bc in nsJSContext::MaybeCC (aHigherProbability=0) at ../../../dom/base/nsJSEnvironment.cpp:3549
#6  0x0000000100479371 in ~nsString [inlined] () at ../../../../content/base/src/nsXMLHttpRequest.cpp:2163
#7  0x0000000100479371 in ~nsDependentString [inlined] () at /Users/gal/workspace/tracemonkey-repository/opt-build/dist/include/nsTDependentString.h:53
#8  0x0000000100479371 in nsXMLHttpRequest::RequestCompleted (this=0x1252a4b80) at ../../../../content/base/src/nsXMLHttpRequest.cpp:2164
#9  0x0000000100479622 in nsXMLHttpRequest::OnStopRequest (this=0x1252a4b80, request=0x116487448, ctxt=<value temporarily unavailable, due to optimizations>, status=0) at ../..

This definitely needs more measuring. I am in gmail, reloading gmail by entering gmail.com into the url bar again.

Comment 7

8 years ago
So... why are we ending up with collection every 5 seconds here, exactly?  We call MaybeCC with aHigherProbability = false.  Then what?

Comment 8

8 years ago
In particular, how is sDelayedCCollectCount ending up > NS_MAX_DELAYED_CCOLLECT?  How many XHRs are in flight here, exactly?

Comment 9

8 years ago
And IntervalCC() is supposed to be a no-op unless 10s have passed since the last CC, for that matter.
(Reporter)

Updated

8 years ago
Depends on: 549538
(Reporter)

Updated

8 years ago
Depends on: 549540
(Reporter)

Updated

8 years ago
Depends on: 549541
(Reporter)

Updated

8 years ago
Depends on: 549544
(Reporter)

Comment 10

8 years ago
The 10s value might hold if you are counting absolute time and not process time since I stopped in gdb. Still, this heuristics seems poor. An idling browser should accumulate so much trash that we need to CC every 10s. Does anyone understand the actual heuristics. We seem to trigger CCs from all over the place, independently. If I stop the browser in gdb and then restart, I sometimes see 2 CCs in sequence with different call stacks.

Comment 11

8 years ago
Ah, yes.  PR_Now is wall-clock time, for sure.

> Still, this heuristics seems poor.

Well, the heuristic is that if more than 10s have passed _and_ a whole bunch of other stuff is true then cc.  See the code in nsJSContext::MaybeCC.

> Does anyone understand the actual heuristics.

Smaug.  ;)
I'd like to have better heuristics :)

The current ones have evolved slowly to handle different cases, like not
regressing tp, not CC too much with gmail (but that was gmail perhaps a year or two ago), CC enough if there is lots of possible garbage (this is a case which may happen with XHR for example - or with any dhtml), try to postpone CC if
user is active...

I wonder if we could split cycle collector's traverse and unlink phases so that
pause would happen more often but would be smaller.

(In reply to comment #10)
> We seem to trigger CCs from all over the
> place, independently.
I don't understand this one. Generally there are 3 ways to trigger CC:
page load, XHR load, and user activity notifier. 
- The first one is there because there used to be GC at that time. Also, 
  changing how CC is called at that time causes tp regressions easily.
- XHR load is there since it usually creates new documents that may
  lead to garbage. This is a case we should probably remove.
  It was added there before there was a way to check suspected object count, 
  IIRC.
- User activity; better to at least try to CC when user might not
  notice it. (Hoping that CC doesn't take too much time when watching videos)
Depends on: 549576
Eventually it would be better if cycle collector could itself notice that
there is lots of possible garbage and call collect() when needed.
This hasn't been touched in a year and a half, so I'm going to close it.  See bug 698919 for further ideas on improving CC performance.
Status: NEW → RESOLVED
Last Resolved: 6 years ago
Resolution: --- → FIXED
Blocks: 698919
No longer blocks: 698919
Blocks: 698919
You need to log in before you can comment on or make changes to this bug.