Last Comment Bug 549533 - improve cycle collector performance
: improve cycle collector performance
Status: RESOLVED FIXED
:
Product: Core
Classification: Components
Component: XPCOM (show other bugs)
: Trunk
: All All
: -- normal (vote)
: ---
Assigned To: Nobody; OK to take it and work on it
:
Mentors:
Depends on: 549538 549540 549541 549544 549576
Blocks: 698919
  Show dependency treegraph
 
Reported: 2010-03-01 19:36 PST by Andreas Gal :gal
Modified: 2012-05-20 12:35 PDT (History)
9 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments

Description Andreas Gal :gal 2010-03-01 19:36:29 PST

    
Comment 1 Andreas Gal :gal 2010-03-01 19:39:54 PST
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
Comment 2 Andreas Gal :gal 2010-03-01 20:05:32 PST
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
Comment 3 Brendan Eich [:brendan] 2010-03-01 20:05:46 PST
The patch in bug 497789 should help js_SweepScopeProperties (renamed to js::SweepScopeProperties) not loom so large.

/be
Comment 4 Andreas Gal :gal 2010-03-01 20:06:22 PST
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
Comment 5 Andreas Gal :gal 2010-03-01 20:08:19 PST
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	}
Comment 6 Andreas Gal :gal 2010-03-01 20:09:09 PST
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 Boris Zbarsky [:bz] (Out June 25-July 6) 2010-03-01 20:39:24 PST
So... why are we ending up with collection every 5 seconds here, exactly?  We call MaybeCC with aHigherProbability = false.  Then what?
Comment 8 Boris Zbarsky [:bz] (Out June 25-July 6) 2010-03-01 20:40:00 PST
In particular, how is sDelayedCCollectCount ending up > NS_MAX_DELAYED_CCOLLECT?  How many XHRs are in flight here, exactly?
Comment 9 Boris Zbarsky [:bz] (Out June 25-July 6) 2010-03-01 20:40:53 PST
And IntervalCC() is supposed to be a no-op unless 10s have passed since the last CC, for that matter.
Comment 10 Andreas Gal :gal 2010-03-01 21:15:05 PST
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 Boris Zbarsky [:bz] (Out June 25-July 6) 2010-03-01 21:22:10 PST
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.  ;)
Comment 12 Olli Pettay [:smaug] (high review load, please consider other reviewers) 2010-03-02 02:08:16 PST
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)
Comment 13 Olli Pettay [:smaug] (high review load, please consider other reviewers) 2010-03-02 02:15:35 PST
Eventually it would be better if cycle collector could itself notice that
there is lots of possible garbage and call collect() when needed.
Comment 14 Andrew McCreight (PTO-ish through 6-29) [:mccr8] 2011-11-30 08:46:03 PST
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.

Note You need to log in before you can comment on or make changes to this bug.