ANR 问题分析

工作中遇到一个ANR问题，记录下自己的想法，随笔而已~ 

ANR 原因是key没有响应，应该是主线程卡住了，key没有被送上来。

07-28 11:51:58.362  3531  3648 I InputDispatcher: Application is not responding: AppWindowToken{5eb8975 token=Token{52048ac ActivityRecord{136365f u0  Skip=false org.droidtv.xxx/.MainActivity t25}}} - Window{8ea8879 u0 org.droidtv.xxx/org.droidtv.xxx.MainActivity}.  It has been 5003.5ms since event, 5001.3ms since wait started.  Reason: 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: 1.

附上同事说的key事件传递流程：

key->decorview->activity->phonewindow->ui->input系统

那么主线程为什么卡住了？从log完全看不出来哪里卡住了，主线程接收的每个key都及时处理了也没有做任何耗时操作。

那就看下trace文件吧。。

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x71b631f0 self=0xe925ce00
  | sysTid=5426 nice=-10 cgrp=default sched=0/0 handle=0xe97f5dc0
  | state=S schedstat=( 11840933002 3428817922 40300 ) utm=1029 stm=154 core=1 HZ=100
  | stack=0xff57d000-0xff57f000 stackSize=8192KB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/5426/stack)
  native: #00 pc 000962b0  /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8)
  native: #01 pc 00064c7d  /apex/com.android.runtime/lib/bionic/libc.so (ioctl+28)
  native: #02 pc 0003aa81  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+208)
  native: #03 pc 0003b56f  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
  native: #04 pc 0003b381  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+112)
  native: #05 pc 00033ed1  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
  native: #06 pc 000db8a3  /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+82)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(BinderProxy.java:510)
  at android.database.BulkCursorProxy.close(BulkCursorNative.java:216)
  at android.database.BulkCursorToCursorAdaptor.close(BulkCursorToCursorAdaptor.java:121)
  at android.database.CursorWrapper.close(CursorWrapper.java:54)
  at android.content.ContentResolver$CursorWrapperInner.close(ContentResolver.java:3336)
  at android.content.CursorLoader.onCanceled(CursorLoader.java:180)
  at android.content.CursorLoader.onCanceled(CursorLoader.java:46)
  at android.content.AsyncTaskLoader.dispatchOnCancelled(AsyncTaskLoader.java:249)
  at android.content.AsyncTaskLoader$LoadTask.onCancelled(AsyncTaskLoader.java:108)
  at android.os.AsyncTask.finish(AsyncTask.java:753)
  at android.os.AsyncTask.access$900(AsyncTask.java:192)
  at android.os.AsyncTask$InternalHandler.handleMessage(AsyncTask.java:772)
  at android.os.Handler.dispatchMessage(Handler.java:107)
  at android.os.Looper.loop(Looper.java:214)
  at android.app.ActivityThread.main(ActivityThread.java:7356)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:547)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)

ANR 期间没有多少log打印，所以trace文件记录应该就是案发现场。从上面的调用栈可以看出，ANR 是发生在LoaderManager的方法中（通过查看源码应该是 restartLoader ）。这部分代码为什么突然就出现问题了？？系统当时在干嘛？？

带着这个疑问查了挺多资料，发现如下两行log可以看出是binder call 阻塞了，在等待对端的回应。这部分是在主线程完成的，所以导致了ANR 的发生。

  native: #03 pc 0003b56f  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
  at android.os.BinderProxy.transactNative(Native method)
 

继续看trace文件， 发现子线程中有十几个任务在做查询，binder call 也都阻塞了。所以应该是binder 线程池被占满了，导致主线程卡住了。

  "AsyncTask #9" prio=5 tid=27 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x136835d0 self=0xd3eee000
  | sysTid=9025 nice=10 cgrp=default sched=0/0 handle=0xbb806230
  | state=S schedstat=( 24568742 45875255 164 ) utm=1 stm=0 core=1 HZ=100
  | stack=0xbb703000-0xbb705000 stackSize=1040KB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/9025/stack)
  native: #00 pc 000962b0  /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8)
  native: #01 pc 00064c7d  /apex/com.android.runtime/lib/bionic/libc.so (ioctl+28)
  native: #02 pc 0003aa81  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+208)
  native: #03 pc 0003b56f  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
  native: #04 pc 0003b381  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+112)
  native: #05 pc 00033ed1  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
  native: #06 pc 000db8a3  /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+82)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(BinderProxy.java:510)
  at android.content.ContentProviderProxy.query(ContentProviderNative.java:421)
  at android.content.ContentResolver.query(ContentResolver.java:944)
  at android.content.ContentResolver.query(ContentResolver.java:880)
  at android.content.CursorLoader.loadInBackground(CursorLoader.java:71)
  at android.content.CursorLoader.loadInBackground(CursorLoader.java:46)
  at android.content.AsyncTaskLoader.onLoadInBackground(AsyncTaskLoader.java:321)
  at android.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:74)
  at android.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:62)
  at android.os.AsyncTask$3.call(AsyncTask.java:378)
  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
  at java.lang.Thread.run(Thread.java:919)
  
  "AsyncTask #23" prio=5 tid=46 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x134d5708 self=0xb9ca7a00
  | sysTid=9108 nice=10 cgrp=default sched=0/0 handle=0xb7b67230
  | state=S schedstat=( 745167 32750 4 ) utm=0 stm=0 core=3 HZ=100
  | stack=0xb7a64000-0xb7a66000 stackSize=1040KB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/9108/stack)
  native: #00 pc 000962b0  /apex/com.android.runtime/lib/bionic/libc.so (__ioctl+8)
  native: #01 pc 00064c7d  /apex/com.android.runtime/lib/bionic/libc.so (ioctl+28)
  native: #02 pc 0003aa81  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+208)
  native: #03 pc 0003b56f  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
  native: #04 pc 0003b381  /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+112)
  native: #05 pc 00033ed1  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
  native: #06 pc 000db8a3  /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+82)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(BinderProxy.java:510)
  at android.content.ContentProviderProxy.query(ContentProviderNative.java:421)
  at android.content.ContentResolver.query(ContentResolver.java:944)
  at android.content.ContentResolver.query(ContentResolver.java:880)
  at android.content.CursorLoader.loadInBackground(CursorLoader.java:71)
  at android.content.CursorLoader.loadInBackground(CursorLoader.java:46)
  at android.content.AsyncTaskLoader.onLoadInBackground(AsyncTaskLoader.java:321)
  at android.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:74)
  at android.content.AsyncTaskLoader$LoadTask.doInBackground(AsyncTaskLoader.java:62)
  at android.os.AsyncTask$3.call(AsyncTask.java:378)
  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
  at java.lang.Thread.run(Thread.java:919)

再回到 log 去看，发现APP接收到按键后就会去做一次数据库查询，这部分逻辑没有问题。但是数据库查询结果一直没有返回。结合trace可以看出，子线程查询时 binder 一直在等待对端数据库返回结果，结果没有返回就会导致阻塞。

下一步就得看下数据库啦~

不足多多，欢迎指教~

参考：

https://www.jianshu.com/p/18f16aba79dd

https://blog.csdn.net/u014630142/article/details/110049575