Android ANR by 'reboot' message

[Filazapovich]

Too many ANRs (~60%) look like:

Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it. Outbound queue length: 0. Wait queue length: 43.)

> main thread:
  #00  pc 000000000001f2ec  /system/lib64/libc.so (syscall+28)
  #01  pc 0000000000022ee0  /system/lib64/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+140)
  #02  pc 0000000000082acc  /system/lib64/libc.so (pthread_cond_wait+60)
  #03  pc 00000000003fec60  lib/arm64/libFamilyIsland.so (android_app_set_activity_state+72)
  at android.app.NativeActivity.onPauseNative (Native method)
  at android.app.NativeActivity.onPause (NativeActivity.java:228)
  at com.dynamo.android.DefoldActivity.onPause (DefoldActivity.java:246)
  at android.app.Activity.performPause (Activity.java:7663)
... [other callstack entries]
> engine thread
  #00  pc 000000000001f2ec  /system/lib64/libc.so (syscall+28)
  #01  pc 0000000000022ee0  /system/lib64/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+140)
  #02  pc 0000000000082acc  /system/lib64/libc.so (pthread_cond_wait+60)
  #03  pc 00000000000172b4  /system/lib64/libwilhelm.so (android::CallbackProtector::requestCbExitAndWait()+72)
  #04  pc 000000000001356c  /system/lib64/libwilhelm.so (android_audioPlayer_preDestroy(CAudioPlayer_struct*)+136)
  #05  pc 0000000000020d30  /system/lib64/libwilhelm.so (CAudioPlayer_PreDestroy(void*)+8)
  #06  pc 00000000000289d4  /system/lib64/libwilhelm.so (IObject_Destroy(SLObjectItf_ const* const*)+72)
  #07  pc 000000000042a4b8  lib/arm64/libFamilyIsland.so (dmDeviceOpenSL::DeviceOpenSLClose(void*)+176)
  #08  pc 000000000041c5c0  lib/arm64/libFamilyIsland.so (dmSound::Finalize()+260)
  #09  pc 00000000000dcd48  lib/arm64/libFamilyIsland.so (dmEngine::Delete(dmEngine::Engine*)+120)
  #10  pc 00000000000dcfcc  lib/arm64/libFamilyIsland.so (_ZN8dmEngineL7InitRunEPN15dmEngineService13EngineServiceEiPPcPFvPNS_6EngineEPvES9_S7_+228)
... [other call stack entries]

ANR with the same call stack:

Input dispatching timed out (com.MelsoftGames.FamilyIslandFarm/com.dynamo.android.DefoldActivity, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 49. Wait queue head age: 9176.9ms.)

main thread:
#00  pc 0000000000042ab8  /system/lib/libc.so (__epoll_pwait+20)
#01  pc 000000000001958f  /system/lib/libc.so (epoll_pwait+26)
#02  pc 000000000001959d  /system/lib/libc.so (epoll_wait+6)
#03  pc 0000000000012ce3  /system/lib/libutils.so (_ZN7android6Looper9pollInnerEi+102)
#04  pc 0000000000012f63  /system/lib/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+130)
#05  pc 0000000000083cbd  /system/lib/libandroid_runtime.so (_ZN7android18NativeMessageQueue8pollOnceEP7_JNIEnvP8_jobjecti+22)
#06  pc 000000000000055d  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+96)
at android.os.MessageQueue.nativePollOnce (Native method)
at android.os.MessageQueue.next (MessageQueue.java:323)
at android.os.Looper.loop (Looper.java:135)
at android.app.ActivityThread.main (ActivityThread.java:5417)
at java.lang.reflect.Method.invoke! (Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run (ZygoteInit.java:726)
at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:616)
no engine thread or no information about call stack in engine thread

Things about that:

• Family Island uses reboot message to reset local state of lua modules in cases with unrecoverable errors related to client-server. User can tap screen while reboot in progress. But this input events is not ignored and cannot be processed.
• Defold is based on Android Native Activity and it uses ALooper_poll...? Input events should be pushed from main thread to engine thread instead of polling them in engine thread.
• May be something wrong with dmDeviceOpenSL::DeviceOpenSLClose?

And please add the name to engine thread for better analysis of ANRs: Thread-13586 (or other thread id as number that is generated by OS is not a good solution)

[jhonnyking]

Hm, looks like a deadlock on the engine thread by the event mutex we have there.

• Do you have more complete logs?
• Do you have a window callback in any scripts? (i.e window.set_listener(window_callback))
• Could you send us your .so file?
• What engine version is this running?

Thanks for the suggestions as well regarding the event loop. It's definitely something we should look into in the future :)

[Filazapovich]

Do you have more complete logs?

I have but i can't download them from Google Play Console. I can prepare this information manually but it requires some time.

Do you have a window callback in any scripts? (i.e window.set_listener(window_callback))

Yep. But i don't see any criminal activity here for focus lost:

    if event == window.WINDOW_EVENT_FOCUS_LOST then
        focus_lost_time = socket.gettime()
    end

What engine version is this running?

1.2.161 (but we have the same ANR reports for 1.2.159, 1.2.157, 1.2.156, 1.2.155 and lower)

[Insality]

We got more ANR's, and the big part of them with trace:

> Main Thread
  #00  pc 000000000007ac48  /system/lib64/libc.so (__epoll_pwait+8)
  #01  pc 0000000000014d48  /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
  #02  pc 0000000000014c18  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
  #03  pc 0000000000127dbc  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
  ..

> Engine Thread
  #00  pc 000000000001f46c  /system/lib64/libc.so (syscall+28)
  #01  pc 00000000000226a4  /system/lib64/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+140)
  #02  pc 000000000008f86c  /system/lib64/libc.so (pthread_cond_wait+60)
  #03  pc 0000000000018920  /system/lib64/libwilhelm.so (android::CallbackProtector::requestCbExitAndWait()+72)
  #04  pc 0000000000013df8  /system/lib64/libwilhelm.so (android_audioPlayer_preDestroy(CAudioPlayer_struct*)+136)
  #05  pc 0000000000022738  /system/lib64/libwilhelm.so (CAudioPlayer_PreDestroy(void*)+8)
  #06  pc 000000000002a1d0  /system/lib64/libwilhelm.so (IObject_Destroy(SLObjectItf_ const* const*)+72)
  #07  pc 0000000000475f28  /data/app/com.MelsoftGames.FamilyIslandFarm-nUewdM87acHpvKjqUjdU2Q==/lib/arm64/libFamilyIsland.so (dmDeviceOpenSL::DeviceOpenSLClose(void*)+164)
  #08  pc 0000000000464890  /data/app/com.MelsoftGames.FamilyIslandFarm-nUewdM87acHpvKjqUjdU2Q==/lib/arm64/libFamilyIsland.so (dmSound::Finalize()+256)
  #09  pc 00000000001125d8  /data/app/com.MelsoftGames.FamilyIslandFarm-nUewdM87acHpvKjqUjdU2Q==/lib/arm64/libFamilyIsland.so (dmEngine::Delete(dmEngine::Engine*)+204)
  #10  pc 00000000001152cc  /data/app/com.MelsoftGames.FamilyIslandFarm-nUewdM87acHpvKjqUjdU2Q==/lib/arm64/libFamilyIsland.so (_ZN8dmEngine6LaunchEiPPcPFvPNS_6EngineEPvES6_S4_+112)
  ...

Looks like deadlock?

As we asked before, may it be something wrong with dmDeviceOpenSL::DeviceOpenSLClose? Should we make another issue on sound ANR's?

We have several ANR traces with some categorization in attachments, it may help you? Separate zip file with only sound ANR's.

We again above of ANR threshold, so we want to investigate in this problems. Ping @britzl @jhonnyking

We still using defold 1.2.161. Reboot game via

timer.delay(0, false, function()
    msg.post("@system:", "reboot")
end)

dmDeviceOpenSL ANR.zip All categorized ANR.zip

[britzl]

We have a loop during shutdown that waits for sound buffers to close. I will investigate a better solution.

[britzl]

This has been fixed and will be released in 1.2.165