API 26 ART crash after extensive app usage

[petekanev]

Problem:
Changes in the art (android runtime) distributed with the update of the OS to Android 26 (Oreo). The error is caused by a failed safety check in one of ART's several garbage collection routines. Code can be found at
https://android.googlesource.com/platform/art/+/android-8.0.0_r4/runtime/gc/collector/concurrent_copying.cc#2435
and
https://android.googlesource.com/platform/art/+/android-8.0.0_r4/runtime/gc/verification.cc#76

the same verifications were not done in previous versions of the runtime. It is not yet clear what the Android team are attempting to prevent by doing that, as the comment left on top of the code addition is vague and does not mean anything without the proper context.

The behavior can be observed when initializing a large number of jni instances (create java objects through js). At some point during a garbage collection the application may, or may not die as a result of the failed check.

Sample stack trace

08-28 10:45:27.762 6169-6169/? A/DEBUG: *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
08-28 10:45:27.762 6169-6169/? A/DEBUG: Build fingerprint: 'google/sdk_gphone_x86/generic_x86:8.0.0/OSR1.170720.005/4205617:userdebug/dev-keys'
08-28 10:45:27.762 6169-6169/? A/DEBUG: Revision: '0'
08-28 10:45:27.762 6169-6169/? A/DEBUG: ABI: 'x86'
08-28 10:45:27.762 6169-6169/? A/DEBUG: pid: 5397, tid: 5408, name: HeapTaskDaemon  >>> com.tns.android_runtime_testapp <<<
08-28 10:45:27.762 6169-6169/? A/DEBUG: signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 0x10004
08-28 10:45:27.762 6169-6169/? A/DEBUG:     eax 00010000  ebx 00000000  ecx 00010000  edx 00010004
08-28 10:45:27.762 6169-6169/? A/DEBUG:     esi b1e21cc0  edi 00000000
08-28 10:45:27.762 6169-6169/? A/DEBUG:     xcs 00000073  xds 0000007b  xes 0000007b  xfs 0000003b  xss 0000007b
08-28 10:45:27.762 6169-6169/? A/DEBUG:     eip b1933090  ebp 96fdf648  esp 96fdf5f0  flags 00010246
08-28 10:45:27.786 6169-6169/? A/DEBUG: backtrace:
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #00 pc 00258090  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying13MarkNonMovingEPNS_6mirror6ObjectES5_NS_12MemberOffsetE+432) - https://android.googlesource.com/platform/art/+/android-8.0.0_r4/runtime/gc/collector/concurrent_copying.h#234
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #01 pc 0025ad57  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying7ProcessEPNS_6mirror6ObjectENS_12MemberOffsetE+359) - https://android.googlesource.com/platform/art/+/android-8.0.0_r4/runtime/gc/collector/concurrent_copying.h#146
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #02 pc 0025a4a1  /system/lib/libart.so (_ZN3art6mirror6Object15VisitReferencesILb1ELNS_17VerifyObjectFlagsE0ELNS_17ReadBarrierOptionE1ENS_2gc9collector17ConcurrentCopying16RefFieldsVisitorES8_EEvRKT2_RKT3_+481)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #03 pc 002528e4  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying19ProcessMarkStackRefEPNS_6mirror6ObjectE+148)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #04 pc 0025202c  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying20ProcessMarkStackOnceEv+684)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #05 pc 00251d5b  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying16ProcessMarkStackEv+43)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #06 pc 0024a594  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying12MarkingPhaseEv+740)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #07 pc 002495d0  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying9RunPhasesEv+736)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #08 pc 00262a03  /system/lib/libart.so (_ZN3art2gc9collector16GarbageCollector3RunENS0_7GcCauseEb+451)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #09 pc 0028fd14  /system/lib/libart.so (_ZN3art2gc4Heap22CollectGarbageInternalENS0_9collector6GcTypeENS0_7GcCauseEb+4484)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #10 pc 002a15a0  /system/lib/libart.so (_ZN3art2gc4Heap12ConcurrentGCEPNS_6ThreadENS0_7GcCauseEb+128)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #11 pc 002ab955  /system/lib/libart.so (_ZN3art2gc4Heap16ConcurrentGCTask3RunEPNS_6ThreadE+53)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #12 pc 002d475b  /system/lib/libart.so (_ZN3art2gc13TaskProcessor11RunAllTasksEPNS_6ThreadE+59)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #13 pc 00480f37  /system/lib/libart.so (_ZN3artL22VMRuntime_runHeapTasksEP7_JNIEnvP8_jobject+55)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #14 pc 002e52c8  /system/framework/x86/boot-core-libart.oat (offset 0xd9000) (dalvik.system.VMRuntime.clampGrowthLimit [DEDUPED]+104)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #15 pc 00638cd2  /system/lib/libart.so (art_quick_invoke_stub+338)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #16 pc 00112b48  /system/lib/libart.so (_ZN3art9ArtMethod6InvokeEPNS_6ThreadEPjjPNS_6JValueEPKc+232)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #17 pc 003231ff  /system/lib/libart.so (_ZN3art11interpreter34ArtInterpreterToCompiledCodeBridgeEPNS_6ThreadEPNS_9ArtMethodEPKNS_7DexFile8CodeItemEPNS_11ShadowFrameEPNS_6JValueE+367)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #18 pc 0031bde1  /system/lib/libart.so (_ZN3art11interpreter6DoCallILb0ELb0EEEbPNS_9ArtMethodEPNS_6ThreadERNS_11ShadowFrameEPKNS_11InstructionEtPNS_6JValueE+817)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #19 pc 0061e141  /system/lib/libart.so (MterpInvokeVirtual+881)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #20 pc 006298a1  /system/lib/libart.so (artMterpAsmInstructionStart+14113)
08-28 10:45:27.786 6169-6169/? A/DEBUG:     #21 pc 002f5f59  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadEPKNS_7DexFile8CodeItemERNS_11ShadowFrameENS_6JValueEb+537)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #22 pc 002fdeda  /system/lib/libart.so (_ZN3art11interpreter33ArtInterpreterToInterpreterBridgeEPNS_6ThreadEPKNS_7DexFile8CodeItemEPNS_11ShadowFrameEPNS_6JValueE+234)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #23 pc 0031bdb5  /system/lib/libart.so (_ZN3art11interpreter6DoCallILb0ELb0EEEbPNS_9ArtMethodEPNS_6ThreadERNS_11ShadowFrameEPKNS_11InstructionEtPNS_6JValueE+773)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #24 pc 0061e141  /system/lib/libart.so (MterpInvokeVirtual+881)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #25 pc 006298a1  /system/lib/libart.so (artMterpAsmInstructionStart+14113)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #26 pc 002f5f59  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadEPKNS_7DexFile8CodeItemERNS_11ShadowFrameENS_6JValueEb+537)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #27 pc 002fdeda  /system/lib/libart.so (_ZN3art11interpreter33ArtInterpreterToInterpreterBridgeEPNS_6ThreadEPKNS_7DexFile8CodeItemEPNS_11ShadowFrameEPNS_6JValueE+234)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #28 pc 0031bdb5  /system/lib/libart.so (_ZN3art11interpreter6DoCallILb0ELb0EEEbPNS_9ArtMethodEPNS_6ThreadERNS_11ShadowFrameEPKNS_11InstructionEtPNS_6JValueE+773)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #29 pc 0061f3a3  /system/lib/libart.so (MterpInvokeInterface+1635)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #30 pc 00629aa1  /system/lib/libart.so (artMterpAsmInstructionStart+14625)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #31 pc 002f5f59  /system/lib/libart.so (_ZN3art11interpreterL7ExecuteEPNS_6ThreadEPKNS_7DexFile8CodeItemERNS_11ShadowFrameENS_6JValueEb+537)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #32 pc 002fddbb  /system/lib/libart.so (_ZN3art11interpreter30EnterInterpreterFromEntryPointEPNS_6ThreadEPKNS_7DexFile8CodeItemEPNS_11ShadowFrameE+139)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #33 pc 0060e50f  /system/lib/libart.so (artQuickToInterpreterBridge+1375)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #34 pc 0063ed2d  /system/lib/libart.so (art_quick_to_interpreter_bridge+77)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #35 pc 00638cd2  /system/lib/libart.so (art_quick_invoke_stub+338)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #36 pc 00112b48  /system/lib/libart.so (_ZN3art9ArtMethod6InvokeEPNS_6ThreadEPjjPNS_6JValueEPKc+232)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #37 pc 00533035  /system/lib/libart.so (_ZN3artL18InvokeWithArgArrayERKNS_33ScopedObjectAccessAlreadyRunnableEPNS_9ArtMethodEPNS_8ArgArrayEPNS_6JValueEPKc+101)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #38 pc 00534652  /system/lib/libart.so (_ZN3art35InvokeVirtualOrInterfaceWithJValuesERKNS_33ScopedObjectAccessAlreadyRunnableEP8_jobjectP10_jmethodIDP6jvalue+466)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #39 pc 00567553  /system/lib/libart.so (_ZN3art6Thread14CreateCallbackEPv+1715)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #40 pc 000709b5  /system/lib/libc.so (_ZL15__pthread_startPv+53)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #41 pc 0002050b  /system/lib/libc.so (__start_thread+75)
08-28 10:45:27.787 6169-6169/? A/DEBUG:     #42 pc 0001eda6  /system/lib/libc.so (__bionic_clone+70)

Solution:
tl;dr: N/A

There is no straightforward way to debug the ART code, and even more so - the ART GC routine. I've had no luck with finding out if it's a reference leak on our end (though there are no visible signs of that), or incorrect object management.

[Plamen5kov]

Another stack from the same issue:

...
GC tried to mark invalid reference 0x1
...
 Runtime aborting...
 Aborting thread:
 "HeapTaskDaemon" prio=5 tid=7 WaitingPerformingGc
   | group="" sCount=0 dsCount=0 flags=0 obj=0x13001cd8 self=0xa4799000
   | sysTid=1593 nice=4 cgrp=default sched=0/0 handle=0x97de0970
   | state=R schedstat=( 86406366 35905080 100 ) utm=7 stm=1 core=0 HZ=100
   | stack=0x97cde000-0x97ce0000 stackSize=1038KB
   | held mutexes= "abort lock"
   native: #00 pc 0047395b  /system/lib/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+203)
   native: #01 pc 0056f42e  /system/lib/libart.so (_ZNK3art6Thread9DumpStackERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMapb+366)
   native: #02 pc 00569cb3  /system/lib/libart.so (_ZNK3art6Thread4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMapb+83)
   native: #03 pc 0054e5f7  /system/lib/libart.so (_ZNK3art10AbortState10DumpThreadERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEPNS_6ThreadE+55)
   native: #04 pc 0054e3aa  /system/lib/libart.so (_ZNK3art10AbortState4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+490)
   native: #05 pc 0053baad  /system/lib/libart.so (_ZN3art7Runtime5AbortEPKc+189)
   native: #06 pc 0053c569  /system/lib/libart.so (_ZN3art7Runtime7AborterEPKc+41)
   native: #07 pc 0011c3d3  /system/lib/libart.so (_ZNSt3__110__function6__funcIPFvPKcENS_9allocatorIS5_EES4_EclEOS3_+35)
   native: #08 pc 0065156a  /system/lib/libart.so (_ZN7android4base10LogMessageD1Ev+1034)
   native: #09 pc 002d5563  /system/lib/libart.so (_ZNK3art2gc12Verification17LogHeapCorruptionENS_6ObjPtrINS_6mirror6ObjectEEENS_12MemberOffsetEPS4_b+1683)
   native: #10 pc 0025807a  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying13MarkNonMovingEPNS_6mirror6ObjectES5_NS_12MemberOffsetE+410)
   native: #11 pc 0025ad57  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying7ProcessEPNS_6mirror6ObjectENS_12MemberOffsetE+359)
   native: #12 pc 0025a4a1  /system/lib/libart.so (_ZN3art6mirror6Object15VisitReferencesILb1ELNS_17VerifyObjectFlagsE0ELNS_17ReadBarrierOptionE1ENS_2gc9collector17ConcurrentCopying16RefFieldsVisitorES8_EEvRKT2_RKT3_+481)
   native: #13 pc 002528e4  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying19ProcessMarkStackRefEPNS_6mirror6ObjectE+148)
   native: #14 pc 002526d0  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying28ProcessThreadLocalMarkStacksEbPNS_7ClosureE+336)
   native: #15 pc 00251fee  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying20ProcessMarkStackOnceEv+622)
   native: #16 pc 00251d5b  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying16ProcessMarkStackEv+43)
   native: #17 pc 0024a594  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying12MarkingPhaseEv+740)
   native: #18 pc 002495d0  /system/lib/libart.so (_ZN3art2gc9collector17ConcurrentCopying9RunPhasesEv+736)
   native: #19 pc 00262a03  /system/lib/libart.so (_ZN3art2gc9collector16GarbageCollector3RunENS0_7GcCauseEb+451)
   native: #20 pc 0028fd14  /system/lib/libart.so (_ZN3art2gc4Heap22CollectGarbageInternalENS0_9collector6GcTypeENS0_7GcCauseEb+4484)
   native: #21 pc 002a15a0  /system/lib/libart.so (_ZN3art2gc4Heap12ConcurrentGCEPNS_6ThreadENS0_7GcCauseEb+128)
   native: #22 pc 002ab955  /system/lib/libart.so (_ZN3art2gc4Heap16ConcurrentGCTask3RunEPNS_6ThreadE+53)
   native: #23 pc 002d475b  /system/lib/libart.so (_ZN3art2gc13TaskProcessor11RunAllTasksEPNS_6ThreadE+59)
   native: #24 pc 00480f37  /system/lib/libart.so (_ZN3artL22VMRuntime_runHeapTasksEP7_JNIEnvP8_jobject+55)

And particulary this line:
GC tried to mark invalid reference 0x1 lead me to this issue, so it's a problem with android O, which, according to AOSP, will be fixed with the next release.

[petekanev]

A fix will be available in the upcoming 3.3.0 release.