android ANR、traces檔案獲取及例項分析
阿新 • • 發佈：2018-11-03
前言：前段時間專案開發中遇到anr的問題，時間緊急，一時間又難以定位，通過臨時方法解決後，最近有時間對ANR的問題做一次份細的解決方案，本文中的解決方案是通過綜合其他部落格後自己再通過例項驗證後得出的可行方案，讀者如遇類似問題可做參考，歡迎評論交流。
1.ANR的模擬
此次寫了一個demo模擬長時間IO造成ANR的情況，然後對logcat內容和traces.txt分析 最終定位到問題程式碼的行號。
首先貼一下演示高IO的核心程式碼：
this.gridView.setOnItemClickListener(new OnItemClickListener() {
@Override 主介面：
操作：點選“檔案選擇器”按鈕開始進行100000次的寫檔案，再點選其他按鈕。由於寫入時間超過5秒，造成另一個按鈕的點選無響應，然後介面彈出ANR彈框提示，模擬完成。
2. 原因分析
2.1 log分析
出現問題首先檢視log資訊，這也是每個開發人員解決所有專案問題的第一個意識，log如下
09-13 04:27:55.077 1627-1641/? E/ActivityManager: ANR in com.example.test_webview_demo (com.example.test_webview_demo/.MainActivity)
PID: 6472
Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 1. Wait queue head age: 5723.8ms.)
Load: 0.17 / 0.06 / 0.06
CPU usage from 162233ms to 0ms ago:
0.1% 6472/com.example.test_webview_demo: 0% user + 0% kernel / faults: 14553 minor
1.3% 1627/system_server: 0.2% user + 1% kernel / faults: 2974 minor
0.8% 1259/surfaceflinger: 0% user + 0.8% kernel
0% 1706/sdcard: 0% user + 0% kernel / faults: 2 minor
0.1% 1264/adbd: 0% user + 0.1% kernel / faults: 3124 minor
0.1% 1726/com.android.systemui: 0% user + 0% kernel / faults: 115 minor
0.1% 1982/com.android.phone: 0% user + 0% kernel / faults: 5 minor
0% 1352/mediaserver: 0% user + 0% kernel / faults: 136 minor
0% 1990/com.android.launcher3: 0% user + 0% kernel / faults: 457 minor
0% 1968/com.google.android.gms.persistent: 0% user + 0% kernel / faults: 4095 minor
0% 2398/com.google.android.gms: 0% user + 0% kernel / faults: 2074 minor
0% 10810/kworker/0:1: 0% user + 0% kernel
0% 3/ksoftirqd/0: 0% user + 0% kernel
0% 12/ksoftirqd/1: 0% user + 0% kernel
0% 8/rcu_preempt: 0% user + 0% kernel
0% 1239/kworker/0:1H: 0% user + 0% kernel
0% 1257/lmkd: 0% user + 0% kernel
0% 1258/servicemanager: 0% user + 0% kernel
0% 1348/netd: 0% user + 0% kernel / faults: 42 minor
0% 1360/fingerprintd: 0% user + 0% kernel
0% 2040/android.process.acore: 0% user + 0% kernel / faults: 16 minor
0% 2074/com.google.android.googlequicksearchbox:search: 0% user + 0% kernel / faults: 639 minor
0% 2108/com.google.process.gapps: 0% user + 0% kernel / faults: 171 minor
0% 6895/kworker/1:2: 0% user + 0% kernel
+0% 11600/logcat: 0% user + 0% kernel
2.8% TOTAL: 0.8% user + 2% kernel + 0% iowait + 0% softirq
CPU usage from 1471ms to 1979ms later:
81% 6472/com.example.test_webview_demo: 29% user + 52% kernel / faults: 1247 minor
50% 6472/st_webview_demo: 19% user + 31% kernel
17% 6482/HeapTaskDaemon: 3.8% user + 13% kernel
15% 6480/FinalizerDaemon: 3.8% user + 11% kernel
23% 1706/sdcard: 5.9% user + 17% kernel
21% 1712/sdcard: 5.9% user + 15% kernel
3.9% 1627/system_server: 0% user + 3.9% kernel
1.8% 1259/surfaceflinger: 0% user + 1.8% kernel
56% TOTAL: 18% user + 38% kernel
log中主要看五行：
1. E/ActivityManager: ANR in com.example.test_webview_demo (com.example.test_webview_demo/.MainActivity)
2. Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago. Wait queue length: 1. Wait queue head age: 5723.8ms.)
3. 2.8% TOTAL: 0.8% user + 2% kernel + 0% iowait + 0% softirq
4. 56% TOTAL: 18% user + 38% kernel
5. PID: 6472
log中搜索”ANR”可以找到這段log,五行分析如下：
- 第一行顯示anr產生的地方為MainActivity,但是沒顯示具體行號，
- 第二行解釋anr產生原因，意思是使用者點選操作響應超時（超過5s），
- 第三行顯示ANR前CPU的使用情況，
- 第四行顯示ANR後CPU的使用情況，
- 第五行顯示發生anr的程序號為6472。
從cpu使用情況看並不是cpu資源不足造成的卡死，所以應該是主執行緒在處理耗時操作造成阻塞引起的anr,從log中只能找出是mainActivity內發生，不夠具體，如果mainActivity比較大的話也很難確定是在什麼地方引起的，所以要進一步定位–分析traces.txt檔案。
2.2 traces檔案
traces.txt系統自動生成的記錄anr等異常的檔案，只記錄java程式碼產生的異常。
2.2.1 traces檔案的獲取
如果手機已經是完全root了的或者是模擬器，可以直接通過DDMS的File Explorer直接匯出來：
如果不是root的手機，可以通過如下adb命令檢視ANR日誌檔案位於哪裡。
adb shell ls /data/anr/
然後通過adb的pull將日誌檔案拉取到指定的路徑。
adb pull /data/anr/traces.txt d:/
但是如果手機沒有進行root，執行adb pull命令就會出現如下提示：
remote object ‘/data/anr/traces.txt’ does not exist
這時候我們可以使用adb將檔案copy一份到sdcard，然後再拉取出來：
adb shell
cat /data/anr/traces.txt >/mnt/sdcard/traces.txt
exit然後可以再從sd卡考到專案目錄：
D:\demos\X5WebDemo>adb pull /mnt/sdcard/traces.txt ./traces.txt
2.2.2 traces檔案分析
traces檔案內容如下：
----- pid 6472 at 2018-09-13 04:27:53 -----
Cmd line: com.example.test_webview_demo
Build fingerprint: 'Android/sdk_google_phone_x86/generic_x86:6.0/MASTER/3738108:userdebug/test-keys'
ABI: 'x86'
Build type: optimized
Zygote loaded classes=3978 post zygote classes=52
Intern table: 44998 strong; 19 weak
JNI: CheckJNI is on; globals=300 (plus 58 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libwebviewchromium_loader.so libjavacore.so (7)
Heap: 31% free, 3MB/4MB; 48092 objects
Dumping cumulative Gc timings
Start Dumping histograms for 17 iterations for partial concurrent mark sweep
ProcessMarkStack: Sum: 32.955ms 99% C.I. 8us-5074.500us Avg: 646.176us Max: 5094us
UpdateAndMarkImageModUnionTable: Sum: 30.824ms 99% C.I. 0.079ms-17.772ms Avg: 1.813ms Max: 19.022ms
SweepMallocSpace: Sum: 28.642ms 99% C.I. 10us-5383us Avg: 842.411us Max: 5390us
FinishPhase: Sum: 19.990ms 99% C.I. 0.022ms-3.723ms Avg: 1.175ms Max: 3.775ms
MarkRootsCheckpoint: Sum: 16.613ms 99% C.I. 44us-5915.999us Avg: 488.617us Max: 6764us
MarkConcurrentRoots: Sum: 14.340ms 99% C.I. 9us-1557.500us Avg: 421.764us Max: 1597us
MarkAllocStackAsLive: Sum: 10.843ms 99% C.I. 21us-2070.250us Avg: 637.823us Max: 2096us
AllocSpaceClearCards: Sum: 5.309ms 99% C.I. 8us-1031.999us Avg: 78.073us Max: 1072us
EnqueueFinalizerReferences: Sum: 4.611ms 99% C.I. 26us-2081us Avg: 271.235us Max: 2178us
ScanGrayAllocSpaceObjects: Sum: 2.640ms 99% C.I. 8us-320us Avg: 77.647us Max: 320us
ProcessCards: Sum: 1.728ms 99% C.I. 41us-95us Avg: 50.823us Max: 95us
MarkNonThreadRoots: Sum: 1.717ms 99% C.I. 11us-690.500us Avg: 50.500us Max: 738us
ReMarkRoots: Sum: 1.693ms 99% C.I. 43us-294us Avg: 99.588us Max: 294us
PreCleanCards: Sum: 1.613ms 99% C.I. 82us-113us Avg: 94.882us Max: 113us
MarkingPhase: Sum: 1.548ms 99% C.I. 75us-159us Avg: 91.058us Max: 159us
(Paused)PausePhase: Sum: 1.519ms 99% C.I. 74us-133us Avg: 89.352us Max: 133us
UpdateAndMarkZygoteModUnionTable: Sum: 1.136ms 99% C.I. 24us-465.999us Avg: 66.823us Max: 475us
MarkRoots: Sum: 1.105ms 99% C.I. 33us-187us Avg: 65us Max: 187us
RecursiveMark: Sum: 1.088ms 99% C.I. 16us-516us Avg: 64us Max: 522us
Sweep: Sum: 978us 99% C.I. 50us-80us Avg: 57.529us Max: 80us
ImageModUnionClearCards: Sum: 968us 99% C.I. 14us-70us Avg: 28.470us Max: 70us
ReclaimPhase: Sum: 946us 99% C.I. 49us-65us Avg: 55.647us Max: 65us
SweepLargeObjects: Sum: 806us 99% C.I. 33us-181us Avg: 47.411us Max: 181us
(Paused)ScanGrayAllocSpaceObjects: Sum: 778us 99% C.I. 8us-162us Avg: 22.882us Max: 162us
ZygoteModUnionClearCards: Sum: 652us 99% C.I. 9us-215.999us Avg: 19.176us Max: 232us
SweepSystemWeaks: Sum: 439us 99% C.I. 12us-60us Avg: 25.823us Max: 60us
ScanGrayImageSpaceObjects: Sum: 391us 99% C.I. 12us-85us Avg: 23us Max: 85us
ProcessReferences: Sum: 368us 99% C.I. 17us-38us Avg: 21.647us Max: 38us
SwapStacks: Sum: 329us 99% C.I. 16us-49us Avg: 19.352us Max: 49us
(Paused)ScanGrayImageSpaceObjects: Sum: 326us 99% C.I. 12us-47us Avg: 19.176us Max: 47us
(Paused)ProcessMarkStack: Sum: 271us 99% C.I. 8us-100us Avg: 15.941us Max: 100us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 238us 99% C.I. 8us-39us Avg: 14us Max: 39us
RevokeAllThreadLocalAllocationStacks: Sum: 223us 99% C.I. 10us-21us Avg: 13.117us Max: 21us
ScanGrayZygoteSpaceObjects: Sum: 204us 99% C.I. 9us-26us Avg: 12us Max: 26us
SwapBitmaps: Sum: 202us 99% C.I. 10us-17us Avg: 11.882us Max: 17us
BindBitmaps: Sum: 165us 99% C.I. 8us-21us Avg: 9.705us Max: 21us
InitializePhase: Sum: 160us 99% C.I. 8us-20us Avg: 9.411us Max: 20us
PreSweepingGcVerification: Sum: 146us 99% C.I. 8us-11us Avg: 8.588us Max: 11us
UnBindBitmaps: Sum: 140us 99% C.I. 8us-10us Avg: 8.235us Max: 10us
FindDefaultSpaceBitmap: Sum: 139us 99% C.I. 8us-9us Avg: 8.176us Max: 9us
SweepZygoteSpace: Sum: 138us 99% C.I. 8us-10us Avg: 8.117us Max: 10us
Done Dumping histograms
partial concurrent mark sweep paused: Sum: 7.348ms 99% C.I. 247us-774us Avg: 432.235us Max: 774us
partial concurrent mark sweep total time: 188.921ms mean time: 11.113ms
partial concurrent mark sweep freed: 324155 objects with total size 44MB
partial concurrent mark sweep throughput: 1.72423e+06/s / 235MB/s
Start Dumping histograms for 225 iterations for sticky concurrent mark sweep
FreeList: Sum: 314.322ms 99% C.I. 11us-1476us Avg: 322.712us Max: 2590us
FinishPhase: Sum: 175.609ms 99% C.I. 15us-2146.875us Avg: 780.484us Max: 3070us
MarkConcurrentRoots: Sum: 150.037ms 99% C.I. 8us-1118.750us Avg: 333.415us Max: 2877us
SweepArray: Sum: 136.460ms 99% C.I. 57us-2675us Avg: 606.488us Max: 6441us
MarkingPhase: Sum: 126.659ms 99% C.I. 143us-1675us Avg: 562.928us Max: 2189us
MarkRootsCheckpoint: Sum: 101.272ms 99% C.I. 42us-1437.500us Avg: 225.048us Max: 2555us
ScanGrayAllocSpaceObjects: Sum: 87.008ms 99% C.I. 8us-800us Avg: 96.675us Max: 1994us
ProcessReferences: Sum: 72.197ms 99% C.I. 24us-799.553us Avg: 320.875us Max: 65711us
ResetStack: Sum: 67.416ms 99% C.I. 11us-1097.916us Avg: 299.626us Max: 3523us
ProcessMarkStack: Sum: 32.287ms 99% C.I. 7us-240.624us Avg: 35.874us Max: 1403us
ProcessCards: Sum: 23.089ms 99% C.I. 40us-237.500us Avg: 51.308us Max: 424us
PreCleanCards: Sum: 23.012ms 99% C.I. 81us-443.750us Avg: 102.275us Max: 659us
(Paused)PausePhase: Sum: 21.670ms 99% C.I. 73us-393.750us Avg: 96.311us Max: 510us
AllocSpaceClearCards: Sum: 21.583ms 99% C.I. 8us-136.111us Avg: 23.981us Max: 207us
ReMarkRoots: Sum: 20.613ms 99% C.I. 41us-396.875us Avg: 91.613us Max: 654us
EnqueueFinalizerReferences: Sum: 16.414ms 99% C.I. 24us-247.916us Avg: 72.951us Max: 2327us
ReclaimPhase: Sum: 15.761ms 99% C.I. 50.030us-493.750us Avg: 70.048us Max: 660us
MarkRoots: Sum: 12.784ms 99% C.I. 32us-346.875us Avg: 56.817us Max: 1521us
ScanGrayImageSpaceObjects: Sum: 12.169ms 99% C.I. 12us-158.333us Avg: 27.042us Max: 1382us
ImageModUnionClearCards: Sum: 11.478ms 99% C.I. 14us-146.875us Avg: 25.506us Max: 225us
MarkNonThreadRoots: Sum: 8.494ms 99% C.I. 10us-137.500us Avg: 18.875us Max: 208us
(Paused)ScanGrayAllocSpaceObjects: Sum: 8.091ms 99% C.I. 8us-143.750us Avg: 17.980us Max: 209us
ScanGrayZygoteSpaceObjects: Sum: 6.616ms 99% C.I. 8us-93.750us Avg: 14.702us Max: 418us
ZygoteModUnionClearCards: Sum: 6.355ms 99% C.I. 8us-87.500us Avg: 14.122us Max: 357us
SweepSystemWeaks: Sum: 5.903ms 99% C.I. 13us-287.500us Avg: 26.235us Max: 602us
ForwardSoftReferences: Sum: 5.885ms 99% C.I. 16us-143.750us Avg: 26.155us Max: 1584us
SwapStacks: Sum: 4.276ms 99% C.I. 16us-93.750us Avg: 19.004us Max: 311us
(Paused)ScanGrayImageSpaceObjects: Sum: 3.961ms 99% C.I. 12us-56us Avg: 17.604us Max: 56us
SwapBitmaps: Sum: 3.705ms 99% C.I. 9us-237.500us Avg: 16.466us Max: 642us
RevokeAllThreadLocalAllocationStacks: Sum: 3.092ms 99% C.I. 9us-49.972us Avg: 13.742us Max: 264us
InitializePhase: Sum: 2.920ms 99% C.I. 8us-193.750us Avg: 12.977us Max: 301us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 2.530ms 99% C.I. 8us-93.750us Avg: 11.244us Max: 105us
FindDefaultSpaceBitmap: Sum: 2.512ms 99% C.I. 8us-93.749us Avg: 11.164us Max: 124us
(Paused)ProcessMarkStack: Sum: 2.472ms 99% C.I. 8us-96.875us Avg: 10.986us Max: 184us
BindBitmaps: Sum: 2.425ms 99% C.I. 8us-49.972us Avg: 10.777us Max: 50us
UnBindBitmaps: Sum: 2.422ms 99% C.I. 8us-96.875us Avg: 10.764us Max: 134us
RecordFree: Sum: 2.200ms 99% C.I. 8us-93.750us Avg: 9.777us Max: 118us
PreSweepingGcVerification: Sum: 2.022ms 99% C.I. 7us-36us Avg: 8.986us Max: 36us
Done Dumping histograms
sticky concurrent mark sweep paused: Sum: 83.450ms 99% C.I. 249us-1225us Avg: 370.888us Max: 1225us
sticky concurrent mark sweep total time: 1.517s mean time: 6.745ms
sticky concurrent mark sweep freed: 879576 objects with total size 514MB
sticky concurrent mark sweep throughput: 579813/s / 339MB/s
Total time spent in GC: 1.706s
Mean GC size throughput: 327MB/s
Mean GC object throughput: 705318 objects/s
Total number of allocations 1251962
Total bytes allocated 562MB
Total bytes freed 558MB
Free memory 1487KB
Free memory until GC 1487KB
Free memory until OOME 316MB
Total memory 4MB
Max memory 320MB
Zygote space size 876KB
Total mutator paused time: 90.798ms
Total time waiting for GC to complete: 4.519ms
Total GC count: 242
Total GC time: 1.706s
Total blocking GC count: 0
Total blocking GC time: 0
Histogram of GC count per 10000 ms: 0:511,4:1
Histogram of blocking GC count per 10000 ms: 0:512
suspend all histogram: Sum: 10.323ms 99% C.I. 16us-1017.599us Avg: 40.482us Max: 1463us
DALVIK THREADS (12):
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 dsCount=0 obj=0x742e7258 self=0xb4034500
| sysTid=6472 nice=0 cgrp=default sched=0/0 handle=0xb7706c00
| state=R schedstat=( 0 0 0 ) utm=172 stm=157 core=1 HZ=100
| stack=0xbf028000-0xbf02a000 stackSize=8MB
| held mutexes= "mutator lock"(shared held)
at java.lang.StringBuilder.<init>(StringBuilder.java:54)
at com.example.test_webview_demo.MainActivity$1.onItemClick(MainActivity.java:115)
at android.widget.AdapterView.performItemClick(AdapterView.java:310)
at android.widget.AbsListView.performItemClick(AbsListView.java:1145)
at android.widget.AbsListView$PerformClick.run(AbsListView.java:3042)
at android.widget.AbsListView.onTouchUp(AbsListView.java:3891)
at android.widget.AbsListView.onTouchEvent(AbsListView.java:3656)
at android.view.View.dispatchTouchEvent(View.java:9294)
at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2547)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2240)
at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2553)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2254)
at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2553)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2254)
at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2553)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2254)
at android.view.ViewGroup.dispatchTransformedTouchEvent(ViewGroup.java:2553)
at android.view.ViewGroup.dispatchTouchEvent(ViewGroup.java:2254)
at com.android.internal.policy.PhoneWindow$DecorView.superDispatchTouchEvent(PhoneWindow.java:2403)
at com.android.internal.policy.PhoneWindow.superDispatchTouchEvent(PhoneWindow.java:1737)
at android.app.Activity.dispatchTouchEvent(Activity.java:2765)
at com.android.internal.policy.PhoneWindow$DecorView.dispatchTouchEvent(PhoneWindow.java:2364)
at android.view.View.dispatchPointerEvent(View.java:9514)
at android.view.ViewRootImpl$ViewPostImeInputStage.processPointerEvent(ViewRootImpl.java:4230)
at android.view.ViewRootImpl$ViewPostImeInputStage.onProcess(ViewRootImpl.java:4096)
at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:3695)
at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:3661)
at android.view.ViewRootImpl$AsyncInputStage.forward(ViewRootImpl.java:3787)
at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:3669)
at android.view.ViewRootImpl$AsyncInputStage.apply(ViewRootImpl.java:3844)
at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:3695)
at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:3661)
at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:3669)
at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:3642)
at android.view.ViewRootImpl.deliverInputEvent(ViewRootImpl.java:5922)
at android.view.ViewRootImpl.doProcessInputEvents(ViewRootImpl.java:5896)
at android.view.ViewRootImpl.enqueueInputEvent(ViewRootImpl.java:5857)
at android.view.ViewRootImpl$WindowInputEventReceiver.onInputEvent(ViewRootImpl.java:6025)
at android.view.InputEventReceiver.dispatchInputEvent(InputEventReceiver.java:185)
at android.os.MessageQueue.nativePollOnce(Native method)
at android.os.MessageQueue.next(MessageQueue.java:323)
at