ANR when calling system service (e.g. telephony service)

Question

since Android 8 I have an increased number of ANRs reported in the Google Play Developer console. All of them have in common that the ANR seems to be not directly related to my code but always related to native system calls. See the following examples:

Example 1:

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x73798b10 self=0x73186a3a00
  | sysTid=12505 nice=0 cgrp=default sched=0/0 handle=0x731d5c49b0
  | state=S schedstat=( 28971945984 27609449667 173830 ) utm=1926 stm=970 core=1 HZ=100
  | stack=0x7fd4e3d000-0x7fd4e3f000 stackSize=8MB
  | held mutexes=
  #00  pc 000000000001db2c  /system/lib64/libc.so (syscall+28)
  #01  pc 00000000000e1f30  /system/lib64/libart.so (_ZN3art17ConditionVariable16WaitHoldingLocksEPNS_6ThreadE+152)
  #02  pc 00000000004e21a4  /system/lib64/libart.so (_ZN3artL12GoToRunnableEPNS_6ThreadE+440)
  #03  pc 00000000004e1fa4  /system/lib64/libart.so (_ZN3art12JniMethodEndEjPNS_6ThreadE+28)
  #04  pc 0000000000991b3c  /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+220)
  at android.os.BinderProxy.transactNative (Native method)
  at android.os.BinderProxy.transact (Binder.java:761)
  at android.os.ServiceManagerProxy.getService (ServiceManagerNative.java:123)
  at android.os.ServiceManager.getService (ServiceManager.java:66)
  at android.telephony.SubscriptionManager.getPhoneId (SubscriptionManager.java:953)
  at android.telephony.TelephonyManager.getNetworkOperatorName (TelephonyManager.java:1693)
  at android.telephony.TelephonyManager.getNetworkOperatorName (TelephonyManager.java:1679)

    [...]

  at com.xx.x.v$1.onSignalStrengthsChanged (MyPhoneStateObserver.java:99)
  at android.telephony.PhoneStateListener$1.handleMessage (PhoneStateListener.java:349)
  at android.os.Handler.dispatchMessage (Handler.java:105)
  at android.os.Looper.loop (Looper.java:164)
  at android.app.ActivityThread.main (ActivityThread.java:6944)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run (Zygote.java:327)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:1374)

Example 2:

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x737b5bb0 self=0x7e0f4a3a00
  | sysTid=24248 nice=0 cgrp=default sched=0/0 handle=0x7e144ca9b0
  | state=S schedstat=( 36923767919 38940772860 261304 ) utm=2358 stm=1334 core=7 HZ=100
  | stack=0x7fdc8c2000-0x7fdc8c4000 stackSize=8MB
  | held mutexes=
  #00  pc 000000000001da2c  /system/lib64/libc.so (syscall+28)
  #01  pc 00000000000e1ee4  /system/lib64/libart.so (_ZN3art17ConditionVariable16WaitHoldingLocksEPNS_6ThreadE+152)
  #02  pc 00000000004e35c8  /system/lib64/libart.so (_ZN3artL12GoToRunnableEPNS_6ThreadE+440)
  #03  pc 00000000004e33c8  /system/lib64/libart.so (_ZN3art12JniMethodEndEjPNS_6ThreadE+28)
  #04  pc 000000000098b14c  /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+220)
  at android.os.BinderProxy.transactNative (Native method)
  at android.os.BinderProxy.transact (Binder.java:751)
  at android.net.INetworkStatsService$Stub$Proxy.getMobileIfaces (INetworkStatsService.java:318)

     [...]

  at com.xx.(MyPhoneStateObserver.java)
  at android.telephony.PhoneStateListener$1.handleMessage (PhoneStateListener.java:331)
  at android.os.Handler.dispatchMessage (Handler.java:108)
  at android.os.Looper.loop (Looper.java:166)
  at android.app.ActivityThread.main (ActivityThread.java:7425)
  at java.lang.reflect.Method.invoke (Native method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run (Zygote.java:245)
  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:921)

Open questions

What I can see from these traces is that every time the system seems to be stuck during a service call e.g. to the telephony service. Is there any explanation why this happens? I expect an ANR to occur if the execution time is >~10sec so there must be a deadlock? A possible solution would be to move all the event handling to another thread but this does not explain the issue and I expect that the async execution would also be stuck?

Edit: The funny thing is that all of these ANRs are titled with:

Broadcast of Intent { act=android.intent.action.SCREEN_OFF flg=0x50200010 }

Answer 1

Try following I found a similar error stack for billing:

Do not call any network calls, reading or writing files, operating databases etc in your MyPhoneStateObserver or any broadcast receiver. You might be calling some method which is blocking the application thread. I would advice call these kinds of methods from a separate thread.

Is there any explanation why this happens? I think you should double check your MyPhoneStateObserver class, I guess you are making some network calls, reading or writing files, operating databases or any operation which should be done in the separate thread. The operations/code you have implemented in this class or overridden method try to do it in a separate thread.

I expect an ANR to occur if the execution time is >~10sec so there must be a deadlock? ANR occurs when the main thread is blocked for a few time. Specifically, 5 seconds in an Activity, 10 seconds in a BroadcastReceiver and 20 seconds in a Service.

A possible solution would be to move all the event handling to another thread but this does not explain the issue and I expect that the async execution would also be stuck? Yes, you are right you have to move your code to another thread. But I don't think so asysnctask will work here, in services or background listeners I believe you would need to use thread.

Answer 2

Base on your error code.

Broadcast of Intent { act=android.intent.action.SCREEN_OFF flg=0x50200010 }

Please try using Wakelock. This will prevent system from shutting off your apps process until you relese the wakelock.

You can aquire wakelock as follows

PowerManager powerManager = (PowerManager) getSystemService(POWER_SERVICE);
WakeLock wakeLock = powerManager.newWakeLock(PowerManager.PARTIAL_WAKE_LOCK,
    "MyApp::MyWakelockTag");
wakeLock.acquire();

Please refer documentation for more details. https://developer.android.com/training/scheduling/wakelock#java

Also refer to https://developer.android.com/about/versions/oreo/background As pointed out in comments, android system tries to optimize resources and that may be the issue that's causing ANRs in your case.

Hope this helps.