May 5, 2015

Android: Debug an ANR



There are common mistakes on Android apps that make you have Application Not Responding (ANR) dialogs.

Something like:



Normally it means that either:

  • your UI/main thread is taking more time that it is supposed to doing something (yes, I'm looking at you that are doing network operations on UI/main thread) 
  • or a less common a BroadcastReceiver is taking more than 10s processing.

A good way to try to detect the problem is by fetching the file /data/anr/traces.txt which is generated after a ANR happens on a device (beware that it is overridden after another ANR happens).

You can get it (without root) by using:


adb shell "cp /data/anr/traces.txt /storage/extSdCard/" 
or

adb pull /storage/extSdCard/traces.txt


That offers you a overview of what each thread was doing at the time of the ANR.

Something like:

----- pid 6996 at 2015-01-01 01:01:01 -----
Cmd line: com.example.app

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

"main" prio=5 tid=1 MONITOR
  | group="main" sCount=1 dsCount=0 obj=0x41772508 self=0x41762988
  | sysTid=6992 nice=0 sched=0/0 cgrp=apps handle=1074810672
  | schedstat=( 1682006857 678192128 2118 ) utm=138 stm=29 core=1
  at com.example.app.services.MyService.doStuff(MyService.java:~229)
  - waiting to lock <0x42ad0818> (a com.example.app.services.MyService) held by tid=29 (ThreadPool[#1/1])
  at com.example.app.services.MyService$MyServiceBinder.start(MyService.java:1552)
  at com.example.app.managers.MyManager$1.onServiceConnected(MyManager.java:311)
  at android.app.LoadedApk$ServiceDispatcher.doConnected(LoadedApk.java:1097)
  at android.app.LoadedApk$ServiceDispatcher$RunConnection.run(LoadedApk.java:1114)
  at android.os.Handler.handleCallback(Handler.java:615)
  at android.os.Handler.dispatchMessage(Handler.java:92)
  at android.os.Looper.loop(Looper.java:137)
  at android.app.ActivityThread.main(ActivityThread.java:4918)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:511)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:994)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:761)
  at dalvik.system.NativeStart.main(Native Method)

"Binder_5" prio=5 tid=36 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x42dc9328 self=0x5492f280
  | sysTid=7096 nice=0 sched=0/0 cgrp=apps handle=1418217512
  | schedstat=( 3540036 12268069 85 ) utm=0 stm=0 core=1
  #00  pc 0000cba0  /system/lib/libc.so (__ioctl+8)
  #01  pc 00027ee5  /system/lib/libc.so (ioctl+16)
  #02  pc 00016bfd  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+124)
  #03  pc 000173af  /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+154)
  #04  pc 0001b171  /system/lib/libbinder.so
  #05  pc 0001104f  /system/lib/libutils.so (android::Thread::_threadLoop(void*)+114)
  #06  pc 0004b6f3  /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+66)
  #07  pc 00010bb5  /system/lib/libutils.so
  #08  pc 00012d20  /system/lib/libc.so (__thread_entry+48)
  #09  pc 00012478  /system/lib/libc.so (pthread_create+172)
  at dalvik.system.NativeStart.run(Native Method)

By this ANR log you should look at MyService.java:~229 for your problem!

So...