1085237 - Intermittent test_camera.html | application timed out after 450.0 seconds with no output | application crashed [@ nsCycleCollector::FinishAnyCurrentCollection()] | Assertion failure: mIncrementalPhase == IdlePhase, at ../../../gecko/xpcom/base/nsCycleC

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Carsten Book [:Tomcat]]

Attachment: crash stack

b2g_emulator_vm mozilla-inbound debug test mochitest-debug-10

https://treeherder.mozilla.org/ui/logviewer.html#?job_id=3126441&repo=mozilla-inbound

21:49:29 INFO - DeviceRunner TEST-UNEXPECTED-FAIL | /tests/dom/camera/test/callback/test_camera.html | application timed out after 450.0 seconds with no output 

21:49:29 WARNING - PROCESS-CRASH | /tests/dom/camera/test/callback/test_camera.html | application crashed [@ nsCycleCollector::FinishAnyCurrentCollection()] 

21:50:40 INFO - 10-20 04:41:32.394 F/MOZ_Assert( 785): Assertion failure: mIncrementalPhase == IdlePhase, at ../../../gecko/xpcom/base/nsCycleCollector.cpp:3667

Comment 1

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-20T00:30:08
log: https://treeherder.mozilla.org/ui/logviewer.html#?repo=mozilla-inbound&job_id=3126441
repository: mozilla-inbound
who: tomcat[at]mozilla[dot]com
machine: tst-linux64-spot-094
buildname: b2g_emulator_vm mozilla-inbound debug test mochitest-debug-10
revision: 983af7fa41f5

DeviceRunner TEST-UNEXPECTED-FAIL | /tests/dom/camera/test/callback/test_camera.html | application timed out after 450.0 seconds with no output
PROCESS-CRASH | /tests/dom/camera/test/callback/test_camera.html | application crashed [@ nsCycleCollector::FinishAnyCurrentCollection()]
Return code: 247
10-20 04:41:32.394 F/MOZ_Assert(  785): Assertion failure: mIncrementalPhase == IdlePhase, at ../../../gecko/xpcom/base/nsCycleCollector.cpp:3667
Return code: 1

Comment 2

[ISHIKAWA, Chiaki]

I am afraid that the bug is not fixed properly.

Please see below. Or should I open a new bugzilla entry?

This is a memo which I prepared to post to bugzilla when I noticed that
this existing entry seems to address the same issue.

My platform:
64-bit Debian GNU/Linux
GCC
I am compiling comm-central thunderbird and experienced the issue.

--- begin quote ---
GC errors

Ever since I refreshed the source tree since the end of the year and
about a week ago again, I seem to hit GC errors unusually often.
(As I explain below, this could be due to the slow-down due to many system calls
in a test version, or slow down by valgrind.)

I have seen GC errors maybe once every three months on the average
before.)  But I have seen three GC errors during normal manual test of
thunderbird since the new year when I am debugging an issue with
buffered output when thunderbird download messages from POP3 server.

And, I am afraid that I hit the GC error
*very often* if I run thunderbird under valgrind.
This interferes with  my attempt to run thunderbird under valgrind
for its |make mozmill| and  |make xpcshell-tests|, too.

I think valgrind skews the timing of execution very much and it seems
to extend the timing window of vulnerability (so to speak) so that
events that may not cause GC problems usually can cause problems easily under valgrind.

The particular problem I see is as follows.

Assertion failure: mIncrementalPhase == IdlePhase || (mIncrementalPhase == ScanAndCollectWhitePhase && mActivelyCollecting) (FinishAnyCurrentCollection should finish the collection, unless we've reentered the CC during unlinking)

Trace by valgrind when such error occurs is given below.
Below the numeric dump, valgrind gives symbolic backtrace.

I suspect that because of the execution slow down due to valgrind,
some timing issues not properly handled by locks, etc. manifest easily under valgrind.

Note that I also saw the GC errors during normal test when TB was
proceeding at crawling speed due to some I/O issues when I saw GC
errors. (Many Flush(), and Seek activities that cause slowdown.) 
So I suspect that prolonged execution of non-GC code might contribute to the issue.

Potential Culprit:

The name I see in the stacktrace is very suspicious: 
>==21811== by 0xB0F4E79: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3361) 

Maybe a previous GC activity triggered by this "periodic full gc" may not have
ended by the time next invocation of full gc?  

This I say because I see the name of maybePeriodicFullGC() *TWICE* in
the stack trace.

LISTING:  Stack trace from valgrind when the error occurred and TB crashed.

Note that the particular cause of the valgrind dump,
>==21811== Invalid write of size 4
is caused by the abort (write to null pointer) inside
MOZ_ASSERT().

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:3713
#01: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xf1e648]
#02: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xf1e6ab]
#03: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xf1e77c]
#04: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xf13d1c]
#05: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xf13db9]
#06: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x4a66b8b]
#07: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x4a66db2]
#08: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x4a66e7a]
#09: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x49f50f6]
#10: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x1fb7cd2]
#11: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x1860eba]
#12: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0x1855d61]
#13: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xfb489d]
#14: ???[/REF-OBJ-DIR/objdir-tb3/dist/bin/libxul.so +0xfb3d17]
==21811== Invalid write of size 4
==21811==    at 0x75AC648: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3711)
==21811==    by 0x75AC6AA: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3696)
==21811==    by 0x75AC77B: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4244)
==21811==    by 0x75A1D1B: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1267)
==21811==    by 0x75A1DB8: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:753)
==21811==    by 0xB0F4B8A: js::gc::GCRuntime::collect(bool, js::SliceBudget&, js::JSGCInvocationKind, JS::gcreason::Reason) (jsgc.cpp:6306)
==21811==    by 0xB0F4DB1: js::gc::GCRuntime::gcSlice(js::JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6372)
==21811==    by 0xB0F4E79: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3361)
==21811==    by 0xB0830F5: JS_MaybeGC(JSContext*) (jsapi.cpp:1638)
==21811==    by 0x8645CD1: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
==21811==    by 0x7EEEEB9: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)
==21811==    by 0x7EE3D60: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJS.cpp:532)
==21811==    by 0x764289C: PrepareAndDispatch (xptcstubs_x86_64_linux.cpp:122)
==21811==    by 0x7641D16: SharedStub (in /REF-OBJ-DIR/objdir-tb3/toolkit/library/libxul.so)
==21811==    by 0x75D8391: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverList.cpp:100)
==21811==    by 0x75D8F5D: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverService.cpp:329)
==21811==    by 0x8769918: nsJSContext::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (nsJSEnvironment.cpp:1944)
==21811==    by 0x7EC3F75: XPCJSRuntime::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (XPCJSRuntime.cpp:709)
==21811==    by 0x75AAD25: nsCycleCollector::CleanupAfterCollection() (nsCycleCollector.cpp:3563)
==21811==    by 0x75AC067: nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool) (nsCycleCollector.cpp:3650)
==21811==    by 0x75AC623: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3709)
==21811==    by 0x75AC6AA: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3696)
==21811==    by 0x75AC77B: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4244)
==21811==    by 0x75A1D1B: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1267)
==21811==    by 0x75A1DB8: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:753)
==21811==    by 0xB0F4B8A: js::gc::GCRuntime::collect(bool, js::SliceBudget&, js::JSGCInvocationKind, JS::gcreason::Reason) (jsgc.cpp:6306)
==21811==    by 0xB0F4DB1: js::gc::GCRuntime::gcSlice(js::JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6372)
==21811==    by 0xB0F4E79: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3361)
==21811==    by 0xB0830F5: JS_MaybeGC(JSContext*) (jsapi.cpp:1638)
==21811==    by 0x8645CD1: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
==21811==    by 0x7EEEEB9: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)
==21811==    by 0x7EE3D60: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJS.cpp:532)
==21811==    by 0x764289C: PrepareAndDispatch (xptcstubs_x86_64_linux.cpp:122)
==21811==    by 0x7641D16: SharedStub (in /REF-OBJ-DIR/objdir-tb3/toolkit/library/libxul.so)
==21811==    by 0xA048958: nsTreeBodyFrame::PaintTwisty(int, nsTreeColumn*, nsRect const&, nsPresContext*, nsRenderingContext&, nsRect const&, int&, int&) (nsTreeBodyFrame.cpp:3329)
==21811==    by 0xA04C4E6: nsTreeBodyFrame::PaintCell(int, nsTreeColumn*, nsRect const&, nsPresContext*, nsRenderingContext&, nsRect const&, int&, nsPoint) (nsTreeBodyFrame.cpp:3264)
==21811==    by 0xA04D131: nsTreeBodyFrame::PaintRow(int, nsRect const&, nsPresContext*, nsRenderingContext&, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:3056)
==21811==    by 0xA04D82C: nsTreeBodyFrame::PaintTreeBody(nsRenderingContext&, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:2854)
==21811==    by 0xA04DCD5: PaintTreeBody(nsIFrame*, nsRenderingContext*, nsRect const&, nsPoint) (nsTreeBodyFrame.cpp:2774)
==21811==    by 0x9E27A31: nsDisplayGeneric::Paint(nsDisplayListBuilder*, nsRenderingContext*) (nsDisplayList.h:1958)
==21811==    by 0x9D0FE7C: mozilla::FrameLayerBuilder::PaintItems(nsTArray<mozilla::FrameLayerBuilder::ClippedDisplayItem>&, nsIntRect const&, gfxContext*, nsRenderingContext*, nsDisplayListBuilder*, nsPresContext*, nsIntPoint const&, float, float, int) (FrameLayerBuilder.cpp:4434)
==21811==    by 0x9D1555D: mozilla::FrameLayerBuilder::DrawPaintedLayer(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*) (FrameLayerBuilder.cpp:4634)
==21811==    by 0x831A9A3: 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:117)
==21811==    by 0x831A0D7: mozilla::layers::BasicPaintedLayer::Validate(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::ReadbackProcessor*) (BasicPaintedLayer.cpp:188)
==21811==    by 0x830ECA0: mozilla::layers::BasicContainerLayer::Validate(void (*)(mozilla::layers::PaintedLayer*, gfxContext*, nsIntRegion const&, mozilla::layers::DrawRegionClip, nsIntRegion const&, void*), void*, mozilla::layers::ReadbackProcessor*) (BasicContainerLayer.cpp:128)
==21811==    by 0x8316205: 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)
==21811==    by 0x8316C26: 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)
==21811==    by 0x9DA1C0D: nsDisplayList::PaintRoot(nsDisplayListBuilder*, nsRenderingContext*, unsigned int) (nsDisplayList.cpp:1643)
==21811==    by 0x9DD7733: nsLayoutUtils::PaintFrame(nsRenderingContext*, nsIFrame*, nsRegion const&, unsigned int, unsigned int) (nsLayoutUtils.cpp:3180)
==21811==    by 0x9E03CCE: PresShell::Paint(nsView*, nsRegion const&, unsigned int) (nsPresShell.cpp:6345)
==21811==  Address 0x0 is not stack'd, malloc'd or (recently) free'd
==21811== 
{
   <insert_a_suppression_name_here>
   ...

TIA

PS: 

Note that I checked the stack dump of a few other GC-related crashes,  and
they match all the way to

>==27914==    by 0xB0830A5: JS_MaybeGC(JSContext*) (jsapi.cpp:1638)
>==27914==    by 0x8645C85: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
>==27914==    by 0x7EEEE6F: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)

The above three lines were taken from another dump. JS_MaybeGC calls other GC-related routines which eventually
crashed and dump shows the same lines from JS_MaybeGC to the top.

Also, there were again *TWO* instances of maybePeriodicFullGC in the stack trace.
It is very suspicious.

From another stack dump.

==27914== Invalid write of size 4
==27914==    at 0x75AC5FE: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3711)
==27914==    by 0x75AC660: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3696)
==27914==    by 0x75AC731: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4244)
==27914==    by 0x75A1CD1: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1267)
==27914==    by 0x75A1D6E: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:753)
==27914==    by 0xB0F4B3A: js::gc::GCRuntime::collect(bool, js::SliceBudget&, js::JSGCInvocationKind, JS::gcreason::Reason) (jsgc.cpp:6306)
==27914==    by 0xB0F4D61: js::gc::GCRuntime::gcSlice(js::JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6372)
==27914==    by 0xB0F4E29: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3361)
==27914==    by 0xB0830A5: JS_MaybeGC(JSContext*) (jsapi.cpp:1638)
==27914==    by 0x8645C85: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
==27914==    by 0x7EEEE6F: nsXPCWrappedJSClass::CallMethod(nsXPCWrappedJS*, unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJSClass.cpp:1427)
==27914==    by 0x7EE3D16: nsXPCWrappedJS::CallMethod(unsigned short, XPTMethodDescriptor const*, nsXPTCMiniVariant*) (XPCWrappedJS.cpp:532)
==27914==    by 0x7642852: PrepareAndDispatch (xptcstubs_x86_64_linux.cpp:122)
==27914==    by 0x7641CCC: SharedStub (in /REF-OBJ-DIR/objdir-tb3/toolkit/library/libxul.so)
==27914==    by 0x75D8347: nsObserverList::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverList.cpp:100)
==27914==    by 0x75D8F13: nsObserverService::NotifyObservers(nsISupports*, char const*, char16_t const*) (nsObserverService.cpp:329)
==27914==    by 0x87698CC: nsJSContext::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (nsJSEnvironment.cpp:1944)
==27914==    by 0x7EC3F2B: XPCJSRuntime::EndCycleCollectionCallback(mozilla::CycleCollectorResults&) (XPCJSRuntime.cpp:709)
==27914==    by 0x75AACDB: nsCycleCollector::CleanupAfterCollection() (nsCycleCollector.cpp:3563)
==27914==    by 0x75AC01D: nsCycleCollector::Collect(ccType, js::SliceBudget&, nsICycleCollectorListener*, bool) (nsCycleCollector.cpp:3650)
==27914==    by 0x75AC5D9: nsCycleCollector::FinishAnyCurrentCollection() (nsCycleCollector.cpp:3709)
==27914==    by 0x75AC660: nsCycleCollector::PrepareForGarbageCollection() (nsCycleCollector.cpp:3696)
==27914==    by 0x75AC731: nsCycleCollector_prepareForGarbageCollection() (nsCycleCollector.cpp:4244)
==27914==    by 0x75A1CD1: mozilla::CycleCollectedJSRuntime::OnGC(JSGCStatus) (CycleCollectedJSRuntime.cpp:1267)
==27914==    by 0x75A1D6E: mozilla::CycleCollectedJSRuntime::GCCallback(JSRuntime*, JSGCStatus, void*) (CycleCollectedJSRuntime.cpp:753)
==27914==    by 0xB0F4B3A: js::gc::GCRuntime::collect(bool, js::SliceBudget&, js::JSGCInvocationKind, JS::gcreason::Reason) (jsgc.cpp:6306)
==27914==    by 0xB0F4D61: js::gc::GCRuntime::gcSlice(js::JSGCInvocationKind, JS::gcreason::Reason, long) (jsgc.cpp:6372)
==27914==    by 0xB0F4E29: js::gc::GCRuntime::maybePeriodicFullGC() (jsgc.cpp:3361)
==27914==    by 0xB0830A5: JS_MaybeGC(JSContext*) (jsapi.cpp:1638)
==27914==    by 0x8645C85: mozilla::dom::AutoEntryScript::~AutoEntryScript() (ScriptSettings.cpp:560)
	     .... rest omitted ...


--- end quote ---

Probably maybePeriodicFullGC() should not be invoked if previous PeriodicFullGC is still
proceeding. 

TIA

Comment 3

[Andrew McCreight [:mccr8]]

Please file a new XPCOM bug about that issue.  I could believe that we have other issues here.

Comment 4

[Andrew McCreight [:mccr8]]

I just went ahead and filed bug 1120495.