全面解析Android之ANR日志
解決ANR一直是Android 開發者需要掌握的重要技巧，一般從三個方面著手。
開發階段：通過工具檢查各個方法的耗時，卡頓情況，發現一處修改一處。 線上階段：這個階段主要依靠監控工具發現ANR并上報，比如matrix。 分析階段：如果線上用戶發生ANR，并且你獲取了一份日志，這就涉及了本文要分享的內容——ANR日志分析技巧。二、ANR產生機制網上通俗的一段面試答題
ANR——應用無響應，Activity是5秒，BroadCastReceiver是10秒，Service是20秒。
這句話說的很籠統，要想深入分析定位ANR，需要知道更多知識點，一般來說，ANR按產生機制，分為4類：
2.1 輸入事件超時(5s)InputEvent Timeout
a.InputDispatcher發送key事件給 對應的進程的 Focused Window ，對應的window不存在、處于暫停態、或通道(input channel)占滿、通道未注冊、通道異常、或5s內沒有處理完一個事件，就會發生ANR
b.InputDispatcher發送MotionEvent事件有個例外之處：當對應Touched Window的 input waitQueue中有超過0.5s的事件，inputDispatcher會暫停該事件，并等待5s，如果仍舊沒有收到window的‘finish’事件，則觸發ANR
c.下一個事件到達，發現有一個超時事件才會觸發ANR
2.2 廣播類型超時（前臺15s，后臺60s）BroadcastReceiver Timeout
a.靜態注冊的廣播和有序廣播會ANR，動態注冊的非有序廣播并不會ANR
b.廣播發送時，會判斷該進程是否存在，不存在則創建，創建進程的耗時也算在超時時間里
c.只有當進程存在前臺顯示的Activity才會彈出ANR對話框，否則會直接殺掉當前進程
d.當onReceive執行超過閾值（前臺15s，后臺60s），將產生ANR
e.如何發送前臺廣播：Intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)
2.3 服務超時（前臺20s，后臺200s）Service Timeout
a.Service的以下方法都會觸發ANR：onCreate(),onStartCommand(), onStart(), onBind(), onRebind(), onTaskRemoved(), onUnbind(),
onDestroy().
b.前臺Service超時時間為20s，后臺Service超時時間為200s
c.如何區分前臺、后臺執行————當前APP處于用戶態，此時執行的Service則為前臺執行。
d.用戶態：有前臺activity、有前臺廣播在執行、有foreground service執行
2.4 ContentProvider 類型a.ContentProvider創建發布超時并不會ANR
b.使用ContentProviderclient來訪問ContentProverder可以自主選擇觸發ANR，超時時間自己定
client.setDetectNotResponding(PROVIDER_ANR_TIMEOUT);
ps：Activity生命周期超時會不會ANR？——經測試并不會。
override fun onCreate(savedInstanceState: Bundle?) { Thread.sleep(60000) super.onCreate(savedInstanceState) setContentView(R.layout.activity_main)}三、導致ANR的原因
很多開發者認為，那就是耗時操作導致ANR，全部是app應用層的問題。實際上，線上環境大部分ANR由系統原因導致。
3.1 應用層導致ANR（耗時操作）a. 函數阻塞：如死循環、主線程IO、處理大數據
b. 鎖出錯：主線程等待子線程的鎖
c. 內存緊張：系統分配給一個應用的內存是有上限的，長期處于內存緊張，會導致頻繁內存交換，進而導致應用的一些操作超時
3.2 系統導致ANRa. CPU被搶占：一般來說，前臺在玩游戲，可能會導致你的后臺廣播被搶占CPU
b. 系統服務無法及時響應：比如獲取系統聯系人等，系統的服務都是Binder機制，服務能力也是有限的，有可能系統服務長時間不響應導致ANR
c. 其他應用占用的大量內存
四、分析日志發生ANR的時候，系統會產生一份anr日志文件（手機的/data/anr 目錄下，文件名稱可能各廠商不一樣，業內大多稱呼為trace文件），內含如下幾項重要信息。
4.1 CPU 負載Load: 2.62 / 2.55 / 2.25
CPU usage from 0ms to 1987ms later (2020-03-10 08:31:55.169 to 2020-03-10 08:32:17.156):
41% 2080/system_server: 28% user + 12% kernel / faults: 76445 minor 180 major
26% 9378/com.xiaomi.store: 20% user + 6.8% kernel / faults: 68408 minor 68 major
........省略N行.....
66% TOTAL: 20% user + 15% kernel + 28% iowait + 0.7% irq + 0.7% softirq
如上所示：
第一行：1、5、15 分鐘內正在使用和等待使用CPU 的活動進程的平均數 第二行：表明負載信息抓取在ANR發生之后的0~1987ms。同時也指明了ANR的時間點：2020-03-10 08:31:55.169 中間部分：各個進程占用的CPU的詳細情況 最后一行：各個進程合計占用的CPU信息。名詞解釋：
a. user:用戶態,kernel:內核態
b. faults:內存缺頁，minor——輕微的，major——重度，需要從磁盤拿數據
c. iowait:IO使用（等待）占比
d. irq:硬中斷，softirq:軟中斷
注意：
iowait占比很高，意味著有很大可能，是io耗時導致ANR，具體進一步查看有沒有進程faults major比較多。 單進程CPU的負載并不是以100%為上限，而是有幾個核，就有百分之幾百，如4核上限為400%。4.2 內存信息Total number of allocations 476778進程創建到現在一共創建了多少對象
Total bytes allocated 52MB 進程創建到現在一共申請了多少內存
Total bytes freed 52MB 進程創建到現在一共釋放了多少內存
Free memory 777KB 不擴展堆的情況下可用的內存
Free memory until GC 777KBGC前的可用內存
Free memory until OOME 383MBOOM之前的可用內存
Total memory 當前總內存（已用+可用）
Max memory 384MB 進程最多能申請的內存
從含義可以得出結論：**Free memory until OOME**的值很小的時候，已經處于內存緊張狀態。應用可能是占用了過多內存。
另外，除了trace文件中有內存信息，普通的eventlog日志中，也有內存信息（不一定打印）
04-02 22:00:08.195 1531 1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]
以上四個值分別指的是：
Cached Free, Zram, Kernel,NativeCached+Free的內存代表著當前整個手機的可用內存，如果值很小，意味著處于內存緊張狀態。一般低內存的判定閾值為：4G 內存手機以下閥值：350MB，以上閥值則為：450MB
ps:如果ANR時間點前后，日志里有打印onTrimMemory，也可以作為內存緊張的一個參考判斷
4.3 堆棧消息堆棧信息是最重要的一個信息，展示了ANR發生的進程當前所有線程的狀態。
suspend all histogram: Sum: 2.834s 99% C.I. 5.738us-7145.919us Avg: 607.155us Max: 41543us
DALVIK THREADS (248):
'main' prio=5 tid=1 Native
| group='main' sCount=1 dsCount=0 flags=1 obj=0x74b17080 self=0x7bb7a14c00
| sysTid=2080 nice=-2 cgrp=default sched=0/0 handle=0x7c3e82b548
| state=S schedstat=( 757205342094 583547320723 2145008 ) utm=52002 stm=23718 core=5 HZ=100
| stack=0x7fdc995000-0x7fdc997000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0xb0/0xbc
kernel: SyS_epoll_wait+0x288/0x364
kernel: SyS_epoll_pwait+0xb0/0x124
kernel: cpu_switch_to+0x38c/0x2258
native: #00 pc 000000000007cd8c /system/lib64/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000014d48 /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
native: #02 pc 0000000000014c18 /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
native: #03 pc 0000000000127474 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:330)
at android.os.Looper.loop(Looper.java:169)
at com.android.server.SystemServer.run(SystemServer.java:508)
at com.android.server.SystemServer.main(SystemServer.java:340)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:536)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:856)
........省略N行.....
'OkHttp ConnectionPool' daemon prio=5 tid=251 TimedWaiting
| group='main' sCount=1 dsCount=0 flags=1 obj=0x13daea90 self=0x7bad32b400
| sysTid=29998 nice=0 cgrp=default sched=0/0 handle=0x7b7d2614f0
| state=S schedstat=( 951407 137448 11 ) utm=0 stm=0 core=3 HZ=100
| stack=0x7b7d15e000-0x7b7d160000 stackSize=1041KB
| held mutexes=
at java.lang.Object.wait(Native method)
- waiting on <0x05e5732e> (a com.android.okhttp.ConnectionPool)
at com.android.okhttp.ConnectionPool$1.run(ConnectionPool.java:103)
- locked <0x05e5732e> (a com.android.okhttp.ConnectionPool)
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:764)
如上日志所示，本文截圖了兩個線程信息，一個是主線程main，它的狀態是native。
另一個是OkHttp ConnectionPool，它的狀態是TimeWaiting。眾所周知，教科書上說線程狀態有5種：新建、就緒、執行、阻塞、死亡。而Java中的線程狀態有6種，6種狀態都定義在：java.lang.Thread.State中
問題來了，上述main線程的native是什么狀態，哪來的？其實trace文件中的狀態是是CPP代碼中定義的狀態，下面是一張對應關系表。
由此可知，main函數的native狀態是正在執行JNI函數。堆棧信息是我們分析ANR的第一個重要的信息，一般來說：
main線程處于 BLOCK、WAITING、TIMEWAITING狀態，那基本上是函數阻塞導致ANR；
如果main線程無異常，則應該排查CPU負載和內存環境。
五、典型案例分析5.1 主線程無卡頓，處于正常狀態堆棧'main' prio=5 tid=1 Native
| group='main' sCount=1 dsCount=0 flags=1 obj=0x74b38080 self=0x7ad9014c00
| sysTid=23081 nice=0 cgrp=default sched=0/0 handle=0x7b5fdc5548
| state=S schedstat=( 284838633 166738594 505 ) utm=21 stm=7 core=1 HZ=100
| stack=0x7fc95da000-0x7fc95dc000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0xb0/0xbc
kernel: SyS_epoll_wait+0x288/0x364
kernel: SyS_epoll_pwait+0xb0/0x124
kernel: cpu_switch_to+0x38c/0x2258
native: #00 pc 000000000007cd8c /system/lib64/libc.so (__epoll_pwait+8)
native: #01 pc 0000000000014d48 /system/lib64/libutils.so (android::Looper::pollInner(int)+148)
native: #02 pc 0000000000014c18 /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+60)
native: #03 pc 00000000001275f4 /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:330)
at android.os.Looper.loop(Looper.java:169)
at android.app.ActivityThread.main(ActivityThread.java:7073)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:536)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:876)
上述主線程堆棧就是一個很正常的空閑堆棧，表明主線程正在等待新的消息。
如果ANR日志里主線程是這樣一個狀態，那可能有兩個原因：
該ANR是CPU搶占或內存緊張等其他因素引起 這份ANR日志抓取的時候，主線程已經恢復正常遇到這種空閑堆棧，可以按照第3節的方法去分析CPU、內存的情況。其次可以關注抓取日志的時間和ANR發生的時間是否相隔過久，時間過久這個堆棧就沒有分析意義了。
5.2 主線程執行耗時操作'main' prio=5 tid=1 Runnable
| group='main' sCount=0 dsCount=0 flags=0 obj=0x72deb848 self=0x7748c10800
| sysTid=8968 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
| state=R schedstat=( 24783612979 48520902 756 ) utm=2473 stm=5 core=5 HZ=100
| stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
| held mutexes= 'mutator lock'(shared held)
at com.example.test.MainActivity$onCreate$2.onClick(MainActivity.kt:20)——關鍵行！！！
at android.view.View.performClick(View.java:7187)
at android.view.View.performClickInternal(View.java:7164)
at android.view.View.access$3500(View.java:813)
at android.view.View$PerformClick.run(View.java:27640)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:230)
at android.app.ActivityThread.main(ActivityThread.java:7725)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)
上述日志表明，主線程正處于執行狀態，看堆棧信息可知不是處于空閑狀態，發生ANR是因為一處click監聽函數里執行了耗時操作。
5.3 主線程被鎖阻塞'main' prio=5 tid=1 Blocked
| group='main' sCount=1 dsCount=0 flags=1 obj=0x72deb848 self=0x7748c10800
| sysTid=22838 nice=-10 cgrp=default sched=0/0 handle=0x77cfa75ed0
| state=S schedstat=( 390366023 28399376 279 ) utm=34 stm=5 core=1 HZ=100
| stack=0x7fce68b000-0x7fce68d000 stackSize=8192KB
| held mutexes=
at com.example.test.MainActivity$onCreate$1.onClick(MainActivity.kt:15)
- waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3 ——————關鍵行！！！
at android.view.View.performClick(View.java:7187)
at android.view.View.performClickInternal(View.java:7164)
at android.view.View.access$3500(View.java:813)
at android.view.View$PerformClick.run(View.java:27640)
at android.os.Handler.handleCallback(Handler.java:883)
at android.os.Handler.dispatchMessage(Handler.java:100)
at android.os.Looper.loop(Looper.java:230)
at android.app.ActivityThread.main(ActivityThread.java:7725)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:526)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1034)
........省略N行.....
'WQW TEST' prio=5 tid=3 TimeWating
| group='main' sCount=1 dsCount=0 flags=1 obj=0x12c44230 self=0x772f0ec000
| sysTid=22938 nice=0 cgrp=default sched=0/0 handle=0x77391fbd50
| state=S schedstat=( 274896 0 1 ) utm=0 stm=0 core=1 HZ=100
| stack=0x77390f9000-0x77390fb000 stackSize=1039KB
| held mutexes=
at java.lang.Thread.sleep(Native method)
- sleeping on <0x043831a6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:440)
- locked <0x043831a6> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:356)
at com.example.test.MainActivity$onCreate$2$thread$1.run(MainActivity.kt:22)
- locked <0x01aed1da> (a java.lang.Object)————————————————————關鍵行！！！
at java.lang.Thread.run(Thread.java:919)
這是一個典型的主線程被鎖阻塞的例子；
waiting to lock <0x01aed1da> (a java.lang.Object) held by thread 3
其中等待的鎖是<0x01aed1da>，這個鎖的持有者是線程 3。進一步搜索 “tid=3” 找到線程3， 發現它正在TimeWating。
那么ANR的原因找到了：線程3持有了一把鎖，并且自身長時間不釋放，主線程等待這把鎖發生超時。在線上環境中，常見因鎖而ANR的場景是SharePreference寫入。
5.4 CPU被搶占CPU usage from 0ms to 10625ms later (2020-03-09 14:38:31.633 to 2020-03-09 14:38:42.257):
543% 2045/com.alibaba.android.rimet: 54% user + 89% kernel / faults: 4608 minor 1 major ————關鍵行！！！
99% 674/android.hardware.camera.provider@2.4-service: 81% user + 18% kernel / faults: 403 minor
24% 32589/com.wang.test: 22% user + 1.4% kernel / faults: 7432 minor 1 major
........省略N行.....
如上日志，第二行是釘釘的進程，占據CPU高達543%，搶占了大部分CPU資源，因而導致發生ANR。
5.5內存緊張導致ANR如果有一份日志，CPU和堆棧都很正常（不貼出來了），仍舊發生ANR，考慮是內存緊張。
從CPU第一行信息可以發現，ANR的時間點是2020-10-31 22:38:58.468—CPU usage from 0ms to 21752ms later (2020-10-31 22:38:58.468 to 2020-10-31 22:39:20.220)
接著去系統日志里搜索am_meminfo， 這個沒有搜索到。再次搜索onTrimMemory，果然發現了很多條記錄；
10-31 22:37:19.749 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:37:33.458 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:38:00.153 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:38:58.731 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
10-31 22:39:02.816 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0
可以看出，在發生ANR的時間點前后，內存都處于緊張狀態，level等級是80，查看Android API 文檔；
/** * Level for {@link #onTrimMemory(int)}: the process is nearing the end * of the background LRU list, and if more memory isn’t found soon it will * be killed. */ static final int TRIM_MEMORY_COMPLETE = 80;
可知80這個等級是很嚴重的，應用馬上就要被殺死，被殺死的這個應用從名字可以看出來是桌面，連桌面都快要被殺死，那普通應用能好到哪里去呢？
一般來說，發生內存緊張，會導致多個應用發生ANR，所以在日志中如果發現有多個應用一起ANR了，可以初步判定，此ANR與你的應用無關。
5.6 系統服務超時導致ANR系統服務超時一般會包含BinderProxy.transactNative關鍵字，請看如下日志：
'main' prio=5 tid=1 Native
| group='main' sCount=1 dsCount=0 flags=1 obj=0x727851e8 self=0x78d7060e00
| sysTid=4894 nice=0 cgrp=default sched=0/0 handle=0x795cc1e9a8
| state=S schedstat=( 8292806752 1621087524 7167 ) utm=707 stm=122 core=5 HZ=100
| stack=0x7febb64000-0x7febb66000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x90/0xc4
kernel: binder_thread_read+0xbd8/0x144c
kernel: binder_ioctl_write_read.constprop.58+0x20c/0x348
kernel: binder_ioctl+0x5d4/0x88c
kernel: do_vfs_ioctl+0xb8/0xb1c
kernel: SyS_ioctl+0x84/0x98
kernel: cpu_switch_to+0x34c/0x22c0
native: #00 pc 000000000007a2ac /system/lib64/libc.so (__ioctl+4)
native: #01 pc 00000000000276ec /system/lib64/libc.so (ioctl+132)
native: #02 pc 00000000000557d4 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+252)
native: #03 pc 0000000000056494 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
native: #04 pc 00000000000562d0 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+216)
native: #05 pc 000000000004ce1c /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+72)
native: #06 pc 00000000001281c8 /system/lib64/libandroid_runtime.so (???)
native: #07 pc 0000000000947ed4 /system/framework/arm64/boot-framework.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+196)
at android.os.BinderProxy.transactNative(Native method) ————————————————關鍵行！！！
at android.os.BinderProxy.transact(Binder.java:804)
at android.net.IConnectivityManager$Stub$Proxy.getActiveNetworkInfo(IConnectivityManager.java:1204)—關鍵行！
at android.net.ConnectivityManager.getActiveNetworkInfo(ConnectivityManager.java:800)
at com.xiaomi.NetworkUtils.getNetworkInfo(NetworkUtils.java:2)
at com.xiaomi.frameworkbase.utils.NetworkUtils.getNetWorkType(NetworkUtils.java:1)
at com.xiaomi.frameworkbase.utils.NetworkUtils.isWifiConnected(NetworkUtils.java:1)
從堆棧可以看出獲取網絡信息發生了ANR：getActiveNetworkInfo。
系統的服務都是Binder機制（16個線程），服務能力也是有限的，有可能系統服務長時間不響應導致ANR。如果其他應用占用了所有Binder線程，那么當前應用只能等待。
可進一步搜索：blockUntilThreadAvailable關鍵字：
at android.os.Binder.blockUntilThreadAvailable(Native method)
如果有發現某個線程的堆棧，包含此字樣，可進一步看其堆棧，確定是調用了什么系統服務。此類ANR也是屬于系統環境的問題，如果某類型機器上頻繁發生此問題，應用層可以考慮規避策略。
以上就是全面解析Android之ANR日志的詳細內容，更多關于Android ANR日志的資料請關注好吧啦網其它相關文章！
相關文章：
網公網安備