ANR originating in Realm?

hanspeide commented 8 years ago

I have an app that never sleeps, with the screen always on. When I leave it on overnight I find it unresponsive in the morning, and when touching the screen it is eventually killed with an ANR. The only thing in traces.txt that points to my app also points to Realm, though I'm by know means certain that this is a Realm issue.

Expected Results

App is responsive.

Actual Results

App is unresponsive, and is eventually killed with ANR being the cause.

In traces.txt I see this:

DALVIK THREADS (71):
"main" prio=5 tid=1 WaitingForDebuggerSend
  | group="main" sCount=1 dsCount=0 obj=0x73fc2000 self=0xb7bd2108
  | sysTid=25274 nice=0 cgrp=default sched=0/0 handle=0xb6f4ebec
  | state=S schedstat=( 2907599942863 359726878192 2637837 ) utm=262131 stm=28628 core=3 HZ=100
  | stack=0xbe186000-0xbe188000 stackSize=8MB
  | held mutexes=
  kernel: futex_wait_queue_me+0xf0/0x154
  kernel: futex_wait+0xe8/0x214
  kernel: do_futex+0xcc/0x934
  kernel: SyS_futex+0xec/0x154
  kernel: ret_fast_syscall+0x0/0x30
  native: #00 pc 0000f9a8  /system/lib/libc.so (syscall+28)
  native: #01 pc 000a7edf  /system/lib/libart.so (art::Mutex::ExclusiveLock(art::Thread*)+318)
  native: #02 pc 0018e3c5  /system/lib/libart.so (art::JDWP::JdwpState::SendBufferedRequest(unsigned int, std::__1::vector<iovec, std::__1::allocator<iovec> > const&)+276)
  native: #03 pc 001854e9  /system/lib/libart.so (art::JDWP::JdwpState::DdmSendChunkV(unsigned int, iovec const*, int)+704)
  native: #04 pc 000ea309  /system/lib/libart.so (art::Dbg::DdmSendChunk(unsigned int, unsigned int, unsigned char const*)+36)
  native: #05 pc 000eae2b  /system/lib/libart.so (art::Dbg::DdmSendHeapInfo(art::Dbg::HpifWhen)+978)
  native: #06 pc 000ed01b  /system/lib/libart.so (art::Dbg::GcDidFinish()+326)
  native: #07 pc 0013c9eb  /system/lib/libart.so (art::gc::Heap::CollectGarbageInternal(art::gc::collector::GcType, art::gc::GcCause, bool)+1850)
  native: #08 pc 0013dee9  /system/lib/libart.so (art::gc::Heap::AllocateInternalWithGc(art::Thread*, art::gc::AllocatorType, unsigned int, unsigned int*, unsigned int*, art::mirror::Class**)+232)
  native: #09 pc 00273aaf  /system/lib/libart.so (artAllocObjectFromCodeRosAlloc+742)
  native: #10 pc 000a169b  /system/lib/libart.so (art_quick_alloc_object_rosalloc+10)
  native: #11 pc 006d9d39  /data/dalvik-cache/arm/data@app@no.urbaninfrastructure.bysykkel.supervisor.debug-2@base.apk@classes.dex (Java_io_realm_StationAvailabilityRealmProxy__0003cinit_0003e__Lio_realm_internal_ColumnInfo_2+100)
  at io.realm.StationAvailabilityRealmProxy.<init>(StationAvailabilityRealmProxy.java:59)
  at io.realm.DefaultRealmModuleMediator.newInstance(DefaultRealmModuleMediator.java:147)
  at io.realm.BaseRealm.get(BaseRealm.java:600)
  at io.realm.RealmResults.get(RealmResults.java:206)
  at io.realm.RealmResults$RealmResultsIterator.next(RealmResults.java:730)
  at io.realm.RealmResults$RealmResultsIterator.next(RealmResults.java:705)
  at no.urbaninfrastructure.bysykkel.supervisor.ui.map.SupervisorMapPresenter.renderStationMarkers(SupervisorMapPresenter.java:143)
  at no.urbaninfrastructure.bysykkel.supervisor.ui.map.SupervisorMapPresenter.lambda$listenForAvailabilityUpdates$1(SupervisorMapPresenter.java:131)
  at no.urbaninfrastructure.bysykkel.supervisor.ui.map.SupervisorMapPresenter$$Lambda$4.onChange(unavailable:-1)
  at io.realm.RealmResults.notifyChangeListeners(RealmResults.java:1014)
  at io.realm.HandlerController.notifyAllListeners(HandlerController.java:301)
  at io.realm.HandlerController.realmChanged(HandlerController.java:450)
  at io.realm.HandlerController.handleMessage(HandlerController.java:118)
  at android.os.Handler.dispatchMessage(Handler.java:98)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5254)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:902)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:697)

Steps & Code to Reproduce

Exact steps unknown. I've left the app open during the night, and find it unresponsive in the morning. Line 59 in StationAvailabilityRealmProxy.java is this.proxyState = new ProxyState(no.urbaninfrastructure.bysykkel.supervisor.domain.StationAvailability.class, this);

Version of Realm and tooling

Realm version: 2.0.2

Android Studio version: 2.2

Which Android version and device: 5.1.1, Lenovo Yoga Tab 2 (YT3-X50L)

beeender commented 8 years ago

Hi! It doesn't look like a Realm issue

    public ProxyState(Class<? extends RealmModel> clazzName, E model) {
        this.clazzName = clazzName;
        this.model = model;
    }

Here is the implementation of ProxyState and you can see it is quite a simple function. I am not quit sure why would this happen, but it seems other things are not correct than Realm. Can you share the full log with other threads backtrace as well?

hanspeide commented 8 years ago

Thanks for looking into it. Here's a gist with the full backtrace.

Zhuinden commented 8 years ago

It claims the GC blocked it with an ANR, while you were iterating a result set.

at no.urbaninfrastructure.bysykkel.supervisor.ui.map.SupervisorMapPresenter.renderStationMarkers(SupervisorMapPresenter.java:143)

This SupervisorMapPresenter could be interesting.

beeender commented 8 years ago

GC thread is holding a lock held mutexes= "JdwpNetStateBase lock" i think it is blocking the main thread. But not sure why...

hanspeide commented 8 years ago

Looks like this indeed is a lock occurring somewhere else, and is not related to Realm. Closing. Thanks for taking time to look into it.

realm / realm-java