How to debug Android ANR?
My Android app gets a lot of ANR reports lately in the Google Play console. Since this started to happen when I included Google Analytics in the app, I strongly suspect Analytics to cause it.
Problem is that I know how to debug a crash using the stack trace. But I'm not sure about how to debug an ANR. I guess that an ANR means that the main thread is blocked somewhere. But how to know where it is blocked? See below one of the typical ANR I got lately. How to interpret it and start figuring out where does the app hangs?
PS: Some of the classes / methods in the stacks look weird due to the usage of DexGuard code obfuscator.
ANR report:
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 VMWAIT
| group="main" sCount=1 dsCount=0 obj=0x40022198 self=0xcec8
| sysTid=5001 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=-1345006496
| schedstat=( 1265991222 1037628169 649 )
at dalvik.system.DexFile.openDexFile(Native Method)
at dalvik.system.DexFile.<init>(DexFile.java:103)
at dalvik.system.DexFile.loadDex(DexFile.java:142)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:507)
at o.Ə$鷭$囃.<clinit>((null):-1)
at o.Ə$櫯.onServiceConnected(:-1)
at android.app.LoadedApk$ServiceDispatcher.doConnected(LoadedApk.java:1064)
at android.app.LoadedApk$ServiceDispatcher$RunConnection.run(LoadedApk.java:1081)
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:130)
at android.app.ActivityThread.main(ActivityThread.java:3687)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:507)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:867)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:625)
at dalvik.system.NativeStart.main(Native Method)
"Binder Thread #3" prio=5 tid=14 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40624cc0 self=0x27eeb0
| sysTid=5046 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=2499688
| schedstat=( 946046 5981445 3 )
at dalvik.system.NativeStart.run(Native Method)
"Thread-15" prio=5 tid=13 TIMED_WAIT
| group="main" sCount=1 dsCount=0 obj=0x405e2a10 self=0x1c99e0
| sysTid=5020 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1845856
| schedstat=( 41442864 92254646 93 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4050ddb0> (a o.㱽)
at java.lang.Object.wait(Object.java:395)
at o.㱽.run(:723)
at java.lang.Thread.run(Thread.java:1019)
"CookieSyncManager" prio=5 tid=12 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40575550 self=0x1ca5a0
| sysTid=5019 nice=10 sched=0/0 cgrp=[fopen-error:2] handle=1844760
| schedstat=( 793456 13153076 3 )
at android.os.MessageQueue.nativePollOnce(Native Method)
at android.os.MessageQueue.next(MessageQueue.java:119)
at android.os.Looper.loop(Looper.java:117)
at android.webkit.WebSyncManager.run(WebSyncManager.java:90)
at android.webkit.CookieSyncManager.run(CookieSyncManager.java:61)
at java.lang.Thread.run(Thread.java:1019)
"WebViewWorkerThread" prio=5 tid=11 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40572d28 self=0x1cec60
| sysTid=5017 nice=1 sched=0/0 cgrp=[fopen-error:2] handle=1904424
| schedstat=( 21575930 39001463 32 )
at android.os.MessageQueue.nativePollOnce(Native Method)
at android.os.MessageQueue.next(MessageQueue.java:119)
at android.os.Looper.loop(Looper.java:117)
at android.os.HandlerThread.run(HandlerThread.java:60)
"WebViewCoreThread" prio=5 tid=10 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x405ded38 self=0x1c9300
| sysTid=5016 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1872952
| schedstat=( 205108647 198852533 140 )
at android.os.MessageQueue.nativePollOnce(Native Method)
at android.os.MessageQueue.next(MessageQueue.java:119)
at android.os.Looper.loop(Looper.java:117)
at android.webkit.WebViewCore$WebCoreThread.run(WebViewCore.java:685)
at java.lang.Thread.run(Thread.java:1019)
"pool-1-thread-1" prio=5 tid=9 WAIT
| group="main" sCount=1 dsCount=0 obj=0x4050daa0 self=0x1c05b8
| sysTid=5015 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1869904
| schedstat=( 5187987 16571046 6 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4050dc68> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1424)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:337)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2016)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:411)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1021)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1081)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:581)
at java.lang.Thread.run(Thread.java:1019)
"GAThread" prio=5 tid=8 WAIT
| group="main" sCount=1 dsCount=0 obj=0x405a4518 self=0x1b8e58
| sysTid=5014 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1806224
| schedstat=( 288482667 146301269 277 )
at java.lang.Object.wait(Native Method)
- waiting on <0x405a4798> (a java.lang.VMThread)
at java.lang.Thread.parkFor(Thread.java:1424)
at java.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48)
at sun.misc.Unsafe.park(Unsafe.java:337)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:157)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2016)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:411)
at o.뛖.run(:518)
"Binder Thread #2" prio=5 tid=7 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40516ed0 self=0xe4478
| sysTid=5007 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1390912
| schedstat=( 5340576 31036382 32 )
at dalvik.system.NativeStart.run(Native Method)
"Binder Thread #1" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 obj=0x40515cb0 self=0x1534c8
| sysTid=5006 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=577280
| schedstat=( 10803221 33203131 35 )
at dalvik.system.NativeStart.run(Native Method)
"Compiler" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x40511d80 self=0x8cce0
| sysTid=5005 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1146040
| schedstat=( 79406736 76446531 396 )
at dalvik.system.NativeStart.run(Native Method)
"Signal Catcher" daemon prio=5 tid=4 RUNNABLE
| group="system" sCount=0 dsCount=0 obj=0x40511cc0 self=0x117af8
| sysTid=5004 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1145528
| schedstat=( 23651123 21545411 7 )
at dalvik.system.NativeStart.run(Native Method)
"GC" daemon prio=5 tid=3 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x40511c18 self=0x153240
| sysTid=5003 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=1389056
| schedstat=( 367523192 416046141 132 )
at dalvik.system.NativeStart.run(Native Method)
"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 obj=0x40511b60 self=0xe6980
| sysTid=5002 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=944960
| schedstat=( 52612306 103576660 48 )
at dalvik.system.NativeStart.run(Native Method)
Answer
But how to know where it is blocked?
Start by enabling StrictMode and running your app. If you (or Analytics) are doing disk or network I/O on the main application thread, you will find out about it, based upon your chosen penalty style (e.g., log in LogCat):
public void onCreate() {
if (BuildConfig.DEBUG) {
StrictMode.setThreadPolicy(new StrictMode.ThreadPolicy.Builder()
.detectAll()
.penaltyLog()
.build());
}
super.onCreate();
// rest of onCreate() logic here
}