ANR Native method - com.adobe.air.customHandler.callTimeoutFunction

[GeneralVimes]

Hi! My game started was receiving over 1% ANR after I updated it with newest AIR SDK in Nov 2023. And after the further updates to the newer SDKs the ANR remained.

The biggest percentage is the Native method - com.adobe.air.customHandler.callTimeoutFunction

Its main thread look like this:

  #00  pc 0x00000000004bca80  /apex/com.android.art/lib64/libart.so (art::DumpNativeStack+108)
  #01  pc 0x00000000004b0dd4  /apex/com.android.art/lib64/libart.so (art::Thread::DumpStack const+388)
  #02  pc 0x00000000004b0714  /apex/com.android.art/lib64/libart.so (art::DumpCheckpoint::Run+164)
  #03  pc 0x00000000003c177c  /apex/com.android.art/lib64/libart.so (art::Thread::RunCheckpointFunction+148)
  #04  pc 0x0000000000559954  /apex/com.android.art/lib64/libart.so (art::JNI<false>::GetMethodID+1924)
  #05  pc 0x0000000000288964  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #06  pc 0x0000000000288e78  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #07  pc 0x00000000002d08bc  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #08  pc 0x00000000002d97ec  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #09  pc 0x00000000003551ac  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #10  pc 0x0000000000356e24  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #11  pc 0x0000000000634b00  /data/app/~~a4SY_uAaqPjqnSoaKLCD8A==/com.airapport.farm.mine.idle.ludumdare48-vHsoNKVTsclfndLN31q0Yg==/split_config.arm64_v8a.apk (BuildId: 5b82e433c72b49787261d88bc6638e041cdf693d)
  #12  pc 0x0000000000017d64 
  at com.adobe.air.customHandler.callTimeoutFunction (Native method)
  at com.adobe.air.customHandler.handleMessage (customHandler.java:34)
  at android.os.Handler.dispatchMessage (Handler.java:106)
  at android.os.Looper.loopOnce (Looper.java:233)
  at android.os.Looper.loop (Looper.java:344)
  at android.app.ActivityThread.main (ActivityThread.java:8249)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:589)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1071)

I'm using 3 distriqt ANEs: Firebase Analytics, In-App purchases Admob

What can be done to reduce ANR rate?

[GeneralVimes]

I thought that perhaps it's because something heavy is done after the user is made an input. So I moved all the actions associated with the user pressing the buttons to the next frame. And anyway the percentage of ANRs remains the same, even for AIR 51.1.1.3

  #00  pc 0x00000000007aea60  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #01  pc 0x0000000000890d38  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #02  pc 0x0000000000890144  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #03  pc 0x000000000088fd68  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #04  pc 0x000000000088e3c0  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #05  pc 0x000000000088eb10  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #06  pc 0x000000000089bedc  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #07  pc 0x00000000007eda84  /data/app/~~pXdc3f4BR3H5nTSm4uoMHg==/com.airapport.farm.mine.idle.ludumdare48-TcsnR6jTUMfAUyDeHvjNww==/split_config.arm64_v8a.apk (BuildId: bb0e5591aace98ad910ea99346dce640c789d70a)
  #08  pc 0x00000000000060c4 
  at com.adobe.air.customHandler.callTimeoutFunction (Native method)
  at com.adobe.air.customHandler.handleMessage (customHandler.java:34)
  at android.os.Handler.dispatchMessage (Handler.java:106)
  at android.os.Looper.loopOnce (Looper.java:224)
  at android.os.Looper.loop (Looper.java:318)
  at android.app.ActivityThread.main (ActivityThread.java:8727)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:561)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1013)

[hadisn]

I see this ANR always....

[ajwfrost]

This particular call stack is showing it's doing garbage collection - the "finish incremental marking" stage, which does include a call to mark all the "local" stack objects prior to cleaning up/sweeping all the garbage. And the actual top line there shows it's marking a list i.e. an array of objects (maybe using the AS3 Array or Vector types?).

We had been looking into how to try to minimise this kind of issue by ensuring we didn't actually hit the 'finish marking' stage when we are within an ActionScript call stack .. but trying to defer this to the end of the calls ended up causing a general performance hit. And trying to craft a test case for it just means you optimise GC for a very fake case...

So I'm not sure there's much we can do here in the short term: suggestions would be to try to minimise any lists or arrays that are being used within 'stack' memory i.e. locally defined. Although I'm not 100% sure if that would help, I would hope if you're able to reference things like this via some member variables of another object, then the marking may have already happened incrementally (i.e. piece by piece that you don't really notice, every frame).

This kind of scenario would be a candidate for us to highlight if we could add more tools/profiling around the GC process. It's a fairly common issue I think :-(

thanks

[GeneralVimes]

Thank you so much! I'll look for local Array/Vector variables and will make them the appropriate class element, we'll look if something will change

[zach-xhx]

Am I reading correctly that garbage collection causes the entire app to crash? Shouldn't the worst thing ever caused by garbage collection just be a very short pause?

[ajwfrost]

Not quite .. it's possible that the "short pause" becomes a longer pause, depending on how much activity goes on during the garbage collection. And if that gets to 5 seconds, and the user had hit the touchscreen, then the Android system would trigger an 'app not responding' error and shut the app down.

So really it's about making sure the application isn't set up in such a way that garbage collection pauses get to be excessive. We've never actually been able to prove that they get above 5s, in 'real' applications, and it does seem quite excessive, but that's about the only theory left as to why we get some of the ANRs.

[GeneralVimes]

Thank you! After you told that it's connected with the garbage collector I started thinking in this direction. I'm already trying to use pools for objects instead of creating new ones, but found areas in my code where I created new Array inside a function instead of using a temp one. This didn't help much. But then I noticed that my game used too much memory. The reason for it was that I had many visual elements which needed to change its visuals once in a while. So I was using starling.display.MovieClip for them.

Then I checked the memory usage using junkbyte Console and was astonished :D

I reworked my code and instead of MovieClip I descended my visual objects from starling.display.Image, and this helped me save a lot of memory and reduce ANR down to 0.15%

[ajwfrost]

@GeneralVimes thanks for the feedback, that's good to know - interesting that a change from MovieClip to Image is making such a difference!

[GeneralVimes]

In more details, it was because I gave to my MovieClips a Vector of Texture of the length of around 2000 elements. And every starling MovieClip on its creation created a Vector of 2000 MovieClipFrame

As I needed only the function to occasionally change the frame of an object, and didn't need any other MovieClip functions, Image worked well for my needs