1120495 - CC reenters GC reenters CC during CleanupPhase

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Andrew McCreight [:mccr8]]

See bug 1085237 comment 2.  It looks like some JS-implemented XPCOM component is observing cycle-collection-statistics, and ends up triggering a GC.  I think this is just an overly tight exception: reentering the CC should be okay during CleanupPhase, too.

Comment 1

[Andrew McCreight [:mccr8]]

Thanks for reporting this!  I don't know why I didn't think of this when I was writing the patch for the other bug.

Comment 2

[ISHIKAWA, Chiaki]

Thank you for opening this bug.

Today, I noticed the same bug is still in the tree.
FYI, I refreshed the source tree about a day ago.

This GC error is now  a hit or miss affair when debug version of
thunderbird is executed under valgrind/memcheck.

It certain is a rare but valid usage, and above all, I did not see
this frequent GC issues early last year, for example.
(Sorry I did not run TB under valgrind due to hardware since early last summer
until the end of last year. I could have caught the issue if
I ran it often...)

Here is another log from a crash.
I wanted to capture a variable uninitialized issue that was noticed
early January before posting, but I could not since
TB under valgrind exit early due to assertion in GC.
(I came back from a jogging run and found TB exited...)

   ... omission ...
JavaScript strict warning: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///home/ishikawa/.thunderbird/u1ku1i3y.default/extensions/[e-mail]!/bootstrap.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/addon-sdk/lib/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/geckoprofiler/lib/prefs.js, line 81: TypeError: variable value redeclares argument
JavaScript warning: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///home/ishikawa/.thunderbird/u1ku1i3y.default/extensions/[e-mail]!/bootstrap.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/addon-sdk/lib/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/addon-sdk/lib/sdk/clipboard.js, line 123: JavaScript 1.7's let blocks are deprecated
JavaScript warning: resource://gre/modules/addons/XPIProvider.jsm -> jar:file:///home/ishikawa/.thunderbird/u1ku1i3y.default/extensions/[e-mail]!/bootstrap.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/addon-sdk/lib/toolkit/loader.js -> resource://jid0-edalmuivkozlouyij0lpdx548bc-at-jetpack/addon-sdk/lib/sdk/clipboard.js, line 134: JavaScript 1.7's let blocks are deprecated
info: geckoprofiler: tb_init entered.
[27888] WARNING: Workers don't support the 'mem.mem.notify' preference!: file /REF-COMM-CENTRAL/comm-central/mozilla/dom/workers/RuntimeService.cpp, line 581
[27888] WARNING: Subdocument container has no frame: file /REF-COMM-CENTRAL/comm-central/mozilla/layout/base/nsDocumentViewer.cpp, line 2505
++DOMWINDOW == 31 (0x1da39b60) [pid = 27888] [serial = 32] [outer = 0x5fd6620]
Assertion failure: mIncrementalPhase == IdlePhase || (mIncrementalPhase == ScanAndCollectWhitePhase && mActivelyCollecting) (FinishAnyCurrentCollection should finish the collection, unless we've reentered the CC during unlinking), at /REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:3703
#01: nsCycleCollector::FinishAnyCurrentCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:3701)
#02: nsCycleCollector::PrepareForGarbageCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:3687)
#03: nsCycleCollector_prepareForGarbageCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:4235)
#04: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:1264)
#05: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:750)
#06: js::gc::GCRuntime::collect(bool, js::SliceBudget, JS::gcreason::Reason) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:6234 (discriminator 1))
#07: js::gc::GCRuntime::startGC(JSGCInvocationKind, JS::gcreason::Reason, long) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:6308)
#08: js::gc::GCRuntime::maybePeriodicFullGC() (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:3301)
#09: JS_MaybeGC(JSContext*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsapi.cpp:1668)
#10: mozilla::dom::AutoEntryScript::~AutoEntryScript() (/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/ScriptSettings.cpp:547)
#11: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/xpconnect/src/XPCWrappedJSClass.cpp:1428)
#12: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/xpconnect/src/XPCWrappedJS.cpp:533)
#13: PrepareAndDispatch (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:122)
#14: SharedStub (xptcstubs_x86_64_linux.cpp:?)
==27888== Invalid write of size 4
==27888==    at 0x75D113E: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3701)
==27888==    by 0x75D11A0: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3686)
==27888==    by 0x75D1271: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4234)
==27888==    by 0x75D1340: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1263)
==27888==    by 0x75D1385: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:749)
==27888==    by 0xABFB5D1: js::gc::GCRuntime::collect(bool, js::SliceBudget, JS::gcreason::Reason) (jsgc.cpp:6234)
==27888==    by 0xABFC7EA: js::gc::GCRuntime::startGC(JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6307)
==27888==    by 0xABFC86A: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3295)
==27888==    by 0xABFCC2E: JS_MaybeGC(JSContext*) (jsapi.cpp:1667)
==27888==    by 0x846948C: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
==27888==    by 0x7EA2136: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)
==27888==    by 0x7E84C42: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJS.cpp:532)
==27888==    by 0x764E85E: PrepareAndDispatch (xptcstubs_x86_64_linux.cpp:122)
==27888==    by 0x764DCD8: SharedStub (in /REF-OBJ-DIR/objdir-tb3/toolkit/library/libxul.so)
==27888==    by 0x75F9AE7: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverList.cpp:100)
==27888==    by 0x75F9BE6: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverService.cpp:329)
==27888==    by 0x8548BC0: nsJSContext::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (nsJSEnvironment.cpp:1758)
==27888==    by 0x7E6DD59: XPCJSRuntime::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (XPCJSRuntime.cpp:710)
==27888==    by 0x75CDF16: nsCycleCollector::CleanupAfterCollection() (nsCycleCollector.cpp:3553)
==27888==    by 0x75D0B27: nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool) (nsCycleCollector.cpp:3640)
==27888==    by 0x75D1119: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3699)
==27888==    by 0x75D11A0: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3686)
==27888==    by 0x75D1271: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4234)
==27888==    by 0x75D1340: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1263)
==27888==    by 0x75D1385: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:749)
==27888==    by 0xABFB5D1: js::gc::GCRuntime::collect(bool, js::SliceBudget, JS::gcreason::Reason) (jsgc.cpp:6234)
==27888==    by 0xABFC7EA: js::gc::GCRuntime::startGC(JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6307)
==27888==    by 0xABFC86A: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3295)
==27888==    by 0xABFCC2E: JS_MaybeGC(JSContext*) (jsapi.cpp:1667)
==27888==    by 0x846948C: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
==27888==    by 0x7EA2136: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)
==27888==    by 0x7E84C42: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJS.cpp:532)
==27888==    by 0x764E85E: PrepareAndDispatch (xptcstubs_x86_64_linux.cpp:122)
==27888==    by 0x764DCD8: SharedStub (in /REF-OBJ-DIR/objdir-tb3/toolkit/library/libxul.so)
==27888==    by 0x9B93A6C: nsTreeBodyFrame::PaintCell(int, nsTreeColumn*, nsRect const&, nsPresContext*, nsRenderingContext&, nsRect const&, int&, nsPoint) (nsTreeBodyFrame.cpp:3135)
==27888==    by 0x9B950C2: nsTreeBodyFrame::PaintRow(int, nsRect const&, nsPresContext*, nsRenderingContext&, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:3062)
==27888==    by 0x9B9573C: nsTreeBodyFrame::PaintTreeBody(nsRenderingContext&, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:2860)
==27888==    by 0x9B95BE5: PaintTreeBody(nsIFrame*, nsRenderingContext*, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:2780)
==27888==    by 0x9996C8F: nsDisplayGeneric::Paint(nsDisplayListBuilder*, nsRenderingContext*) (nsDisplayList.h:1958)
==27888==    by 0x98AA2DD: mozilla::FrameLayerBuilder::PaintItems(nsTArray<mozilla::FrameLayerBuilder::ClippedDisplayItem>&, nsIntRect const&, gfxContext*, nsRenderingContext*, nsDisplayListBuilder*, nsPresContext*, nsIntPoint const&, float, float, int) (FrameLayerBuilder.cpp:4434)
==27888==    by 0x98AF258: mozilla::FrameLayerBuilder::DrawPaintedLayer(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*) (FrameLayerBuilder.cpp:4634)
==27888==    by 0x81FE671: mozilla::layers::BasicPaintedLayer::PaintBuffer(gfxContext*, nsIntRegion const&, nsIntRegion const&, nsIntRegion const&, bool, mozilla::layers::DrawRegionClip, void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*) (BasicPaintedLayer.h:116)
==27888==    by 0x81F81D5: mozilla::layers::BasicPaintedLayer::Validate(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::ReadbackProcessor*) (BasicPaintedLayer.cpp:188)
==27888==    by 0x81F45DF: mozilla::layers::BasicContainerLayer::Validate(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::ReadbackProcessor*) (BasicContainerLayer.cpp:128)
==27888==    by 0x81FCC51: mozilla::layers::BasicLayerManager::EndTransactionInternal(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::LayerManager::EndTransactionFlags) (BasicLayerManager.cpp:503)
==27888==    by 0x81FD3FA: mozilla::layers::BasicLayerManager::EndTransaction(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::LayerManager::EndTransactionFlags) (BasicLayerManager.cpp:454)
==27888==    by 0x9921159: nsDisplayList::PaintRoot(nsDisplayListBuilder*, nsRenderingContext*, unsigned int) (nsDisplayList.cpp:1646)
==27888==    by 0x9924548: nsLayoutUtils::PaintFrame(nsRenderingContext*, nsIFrame*, nsRegion const&, unsigned int, unsigned int) (nsLayoutUtils.cpp:3191)
==27888==    by 0x9972B96: PresShell::Paint(nsView*, nsRegion const&, unsigned int) (nsPresShell.cpp:6337)
==27888==    by 0x95CC5DA: nsViewManager::ProcessPendingUpdatesPaint(nsIWidget*) (nsViewManager.cpp:443)
==27888==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==27888== 
{
   <insert_a_suppression_name_here>
   Memcheck:Addr4
   fun:_ZN16nsCycleCollector26FinishAnyCurrentCollectionEv
   fun:_ZN16nsCycleCollector27PrepareForGarbageCollectionEv
   fun:_Z44nsCycleCollector_prepareForGarbageCollectionv
   fun:_ZN7mozilla23CycleCollectedJSRuntime4OnGCE10JSGCStatus
   fun:_ZN7mozilla23CycleCollectedJSRuntime10GCCallbackEP9JSRuntime10JSGCStatusPv
   fun:_ZN2js2gc9GCRuntime7collectEbNS_11SliceBudgetEN2JS8gcreason6ReasonE
   fun:_ZN2js2gc9GCRuntime7startGCE18JSGCInvocationKindN2JS8gcreason6ReasonEl
   fun:_ZN2js2gc9GCRuntime19maybePeriodicFullGCEv
   fun:_Z10JS_MaybeGCP9JSContext
   fun:_ZN7mozilla3dom15AutoEntryScriptD1Ev
   fun:_ZN19nsXPCWrappedJSClass10CallMethodEP14nsXPCWrappedJStPK19XPTMethodDescriptorP17nsXPTCMiniVariant
   fun:_ZN14nsXPCWrappedJS10CallMethodEtPK19XPTMethodDescriptorP17nsXPTCMiniVariant
   fun:PrepareAndDispatch
   fun:SharedStub
   fun:_ZN14nsObserverList15NotifyObserversEP11nsISupportsPKcPKDs
   fun:_ZN17nsObserverService15NotifyObserversEP11nsISupportsPKcPKDs
   fun:_ZN11nsJSContext26EndCycleCollectionCallbackERN7mozilla21CycleCollectorResultsE
   fun:_ZN12XPCJSRuntime26EndCycleCollectionCallbackERN7mozilla21CycleCollectorResultsE
   fun:_ZN16nsCycleCollector22CleanupAfterCollectionEv
   fun:_ZN16nsCycleCollector7CollectE6ccTypeRN2js11SliceBudgetEP25nsICycleCollectorListenerb
   fun:_ZN16nsCycleCollector26FinishAnyCurrentCollectionEv
   fun:_ZN16nsCycleCollector27PrepareForGarbageCollectionEv
   fun:_Z44nsCycleCollector_prepareForGarbageCollectionv
   fun:_ZN7mozilla23CycleCollectedJSRuntime4OnGCE10JSGCStatus
}

Program /REF-OBJ-DIR/objdir-tb3/dist/bin/thunderbird-bin (pid = 27888) received signal 11.
Stack:
#01: AsmJSFaultHandler(int, siginfo_t*, void*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/asmjs/AsmJSSignalHandlers.cpp:929)
#02: __restore_rt (sigaction.c:?)
#03: nsCycleCollector::FinishAnyCurrentCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:3701)
#04: nsCycleCollector::PrepareForGarbageCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:3687)
#05: nsCycleCollector_prepareForGarbageCollection() (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/nsCycleCollector.cpp:4235)
#06: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:1264)
#07: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/base/CycleCollectedJSRuntime.cpp:750)
#08: js::gc::GCRuntime::collect(bool, js::SliceBudget, JS::gcreason::Reason) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:6234 (discriminator 1))
#09: js::gc::GCRuntime::startGC(JSGCInvocationKind, JS::gcreason::Reason, long) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:6308)
#10: js::gc::GCRuntime::maybePeriodicFullGC() (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsgc.cpp:3301)
#11: JS_MaybeGC(JSContext*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/src/jsapi.cpp:1668)
#12: mozilla::dom::AutoEntryScript::~AutoEntryScript() (/REF-COMM-CENTRAL/comm-central/mozilla/dom/base/ScriptSettings.cpp:547)
#13: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/xpconnect/src/XPCWrappedJSClass.cpp:1428)
#14: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (/REF-COMM-CENTRAL/comm-central/mozilla/js/xpconnect/src/XPCWrappedJS.cpp:533)
#15: PrepareAndDispatch (/REF-COMM-CENTRAL/comm-central/mozilla/xpcom/reflect/xptcall/md/unix/xptcstubs_x86_64_linux.cpp:122)
#16: SharedStub (xptcstubs_x86_64_linux.cpp:?)
Sleeping for 300 seconds.
Type 'gdb /REF-OBJ-DIR/objdir-tb3/dist/bin/thunderbird-bin 27888' to attach your debugger to this thread.
Done sleeping...


That I am using a full debug version may add to the frequent symptom.
valgrind/memcheck needs to trace more instruction sequence for debug output, and thus
lengthening the timing of window of vulnerability.

I hope this gets fixed soon.

TIA

Comment 3

[Andrew McCreight [:mccr8]]

Yeah, sorry, I just haven't gotten around to fixing this yet.

try run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=c1f3b868c1f6

Comment 4

[Andrew McCreight [:mccr8]]

Attachment: Don't assert if FinishAnyCurrentCollection reenters during CleanupPhase.

Comment 5

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8552687 [details] [diff] [review]
Don't assert if FinishAnyCurrentCollection reenters during CleanupPhase.

># HG changeset patch
># User Andrew McCreight <[e-mail]>
>
>Bug 1120495 - Don't assert if FinishAnyCurrentCollection reenters during CleanupPhase. r=smaug
>
>diff --git a/xpcom/base/nsCycleCollector.cpp b/xpcom/base/nsCycleCollector.cpp
>index d8245f9..afd69fc 100644
>--- a/xpcom/base/nsCycleCollector.cpp
>+++ b/xpcom/base/nsCycleCollector.cpp
>@@ -3687,19 +3687,22 @@ nsCycleCollector::FinishAnyCurrentCollection()
>     return;
>   }
> 
>   SliceBudget unlimitedBudget;
>   PrintPhase("FinishAnyCurrentCollection");
>   // Use SliceCC because we only want to finish the CC in progress.
>   Collect(SliceCC, unlimitedBudget, nullptr);
> 
>+  // If FinishAnyCurrentCollection() failed to finish the current CC, then the CC
s/FinishAnyCurrentCollection/Collect/


>+  // should have reentered,
s/should have/was/ ?

 and it should not still be in the middle of graph building,
>+  // because that phase looks at JS objects that may be about to die.
... and then something. not sure what this comment is trying to say.

Comment 6

[Andrew McCreight [:mccr8]]

I rephrased the comment a bit per IRC discussion with Olli.

https://hg.mozilla.org/integration/mozilla-inbound/rev/725d886f0b06

Comment 7

[ISHIKAWA, Chiaki]

(In reply to Andrew McCreight [:mccr8] from comment #6)
> I rephrased the comment a bit per IRC discussion with Olli.
> 
> https://hg.mozilla.org/integration/mozilla-inbound/rev/725d886f0b06

Thank you.
I report my experience when I get to test the new tree.

CI

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/725d886f0b06