1.背景
8月份安卓出现了一次直播间卡死(ANR)问题，且由于排查难度较大，持续了较长时间。本文针对如何快速定位安卓端出现ANR问题进行总结和探讨.
这里大致补充一下当时的情况,当时看到情景的是从某一个特定的场景下进入直播间后整个直播间界面立刻就卡住了,由于进入直播间后并没有做额外的操作就卡住,这给排查带来了非常大的困难.
2.相关排查方法
我们就以本次直播间卡住问题为例,逐一分析整个问题的排查方法和步骤.这里我想到的方法有两种,
第一种方法就是日志的获取,我们可以获取本地安卓系统提供的anr日志(trace文件)进行分析,也可以获取我们自己平时打点的日志进行分析.
第二种就是结合自己对代码的了解同时结合anr发生的契机,逐一对代码进行注释,然后排查到导致卡住代码的位置.
由于第二种方法比较基础,同时如果是多人开发,并不是所有的代码自己都能了如指掌,可能会加大排查难度和时间.因此我们主要针对第一种方法进行展开了解.
3.手机日志的获取和分析
手机日志的获取,我们可以分为两种.
第一种就是我们的logcat日志,logcat日志包括系统日志和我们自打点的log日志,logcat日志我们可以实时抓取,也可以存在本地,甚至上传到云端.结合日志的打印我们可以推测代码发生的大致位置,然后进行判断.但它具有较大的局限性.
第二种是系统的anr日志,也就是tarce.txt文件,这个日志是专门用来记录发生ANR时app各个线程的活动情况.因此只有anr发生时才会产生该文件.后面我们将重点分析它.
下面我们来分析整个ANR事件的排查流程.
3.1获取ANR日志导出方法
3.1.1 logcat日志获取
获取logcat日志很方便,我们可以直接在AndroidStudio控制台就能看到logcat日志.
如果我们没有AndroidStudio我们也可以通过adb工具来将log日志输入文本文件中,我们只需要在adb的目录下输入如下命令即可:
adb logcat -v time process thread >.\\\logcat.log
这里我们分别打印出了进程号和线程号,以方便后续排查.
3.1.2 trace.txt文件获取
trace.txt是我们分析anr发生时最重要的文件,我们想要获取它,可以采用如下方法:
- 针对Android低版本手机(6.0以下),使用
adb pull data/anr/traces.txt
即可将anr日志,traces.txt文件导出
- 针对Android高版本手机,会有权限的问题.但是谷歌给我们提供了令一个命令,就是bugreport,我们可以使用如下命令
adb bugreport
即可将整体日志导出到当前命令行对应目录下,它是一个压缩包的形式,我们将它解压,然后在FS/data/anr目录下就可以找到traces.txt文件了.
3.2ANR日志分析
3.2.1anr产生的原因
首先我们需要了解一下anr产生情况都有哪些,总结如下:
产生anr的情况有：
（1）Activity按键或触摸事件在特定时间内无响应(5s)
（2）Service在特定时间内无法处理完成(bind，create，start，unbind等等)(前台20s，后台200s)
（3）BroadcastReceiver在特定时间内无法处理完成(前台10S,后台60s
（4）ContentProvider执行超时，20s
上面四种情况其实就是对应的安卓的四大组件的超时情况,从这里我们不难想到,安卓的anr机制其实就是安卓系统本身设计的一种保护性措施,如果四大组建响应超时了那么就会触发android not responding的回应.在开发中我们大多数遇到的情况都是第一种，在主线程做了耗时操作，导致堵塞，然后触发点击事件，无法及时响应.就比如我们8月份出现的一次直播间卡死现象,就是上面所说的第一种情况,我们在主线程做了耗时循环操作,导致所有UI刷新都在进行等待,同时我们如果触摸屏幕也会进行等待,最后会触发anr弹窗.
3.2.2ANR文件解读
3.2.2.1 logcat文件解读
我们在logcat文件中搜索"ANR in"关键字,我们将会得到发生anr时系统给出的log信息,如下图,如果搜索不到这样的信息，我们可以直接跳过这一步，因为可能是手机厂商自己定制系统的时候修改了framework层，所以我们可能看不到。
我们从logcat中一般能找到anr发生的大致位置,以及CPU的占用情况.这个可以帮助我们缩小查找的范围.
例如上面从9392行我们可以解读到anr发生在VideoLiveRoomActivity页面，也就是我们的直播间页面。它描述着下面的内容:
9392 12-25 22:49:41.424 E/ActivityManager( 1535): Reason: Input dispatching timed out
(Waiting to send non-key event because the touched window has not finished processing
certain input events that
9393 were delivered to it over 500.0ms ago. Wait queue length: 8. Wait queue head age: 5573.6ms.)
从这里我们可以看出,它还告诉我们anr发生的原因是在等待一个非关键事件的传递，这个事件可能是一个UI绘制的事件或者别的，这个事件是存在安卓的消息队列中，因此整个消息队列目前都处于阻塞状态中。从这里可以猜想到前面应该有一个耗时操作阻塞了整个队列。
同时，我们继续往下看可以看到下面列出来了不同进程对CPU的占用情况
12-25 22:49:41.424 E/ActivityManager( 1535): CPU usage from 5064ms to 15908ms later (2023-12-25 22:49:30.515 to 2023-12-25 22:49:41.359):
12-25 22:49:41.424 E/ActivityManager( 1535): 105% 26596/com.jingdong.app.mall: 103% user + 2.6% kernel / faults: 7121 minor
12-25 22:49:41.424 E/ActivityManager( 1535): 16% 835/surfaceflinger: 12% user + 4.1% kernel / faults: 529 minor
12-25 22:49:41.424 E/ActivityManager( 1535): 14% 1535/system_server: 9.3% user + 4.7% kernel / faults: 10314 minor 2 major
12-25 22:49:41.424 E/ActivityManager( 1535): 12% 1043/media.codec: 5.7% user + 6.5% kernel / faults: 17482 minor
12-25 22:49:41.424 E/ActivityManager( 1535): 4.4% 770/android.hardware.graphics.composer@2.1-service: 2.1% user + 2.3% kernel / faults: 10 minor
12-25 22:49:41.424 E/ActivityManager( 1535): 2.9% 30680/com.tencent.mobileqq: 1.8% user + 1.1% kernel / faults: 3273 minor 11 major
12-25 22:49:41.424 E/ActivityManager( 1535): 2.6% 993/cnss_diag: 2.2% user + 0.4% kernel
12-25 22:49:41.424 E/ActivityManager( 1535): 2.4% 570/irq/289-synapti: 0% user + 2.4% kernel
显而易见，com.jingdong.app.mall已经占用了105%，说明它以及几乎占满了CPU的负载，这个更加能确定我们代码的某一块正在执行着耗时操作，那么如何找到这个耗时操作呢？我们继续往下看。
3.2.2.2 trace.txt文件解读
我们想要快读定位到anr的位置,那么我就需要对trace文件拥有较为深入的了解.
因此trace.txt文件是我们分析anr发生的过程中最重要的文件，接下来我们就对它进行整体分析
我们先来分析一下trace.txt文件的整体结构,我们可以将文件大致概括为如下:
----- pid 1882 at 2022-10-02 15:37:56 -----
进程1882的详细日志
----- end 1882 ---------- pid 1565 at 2022-10-02 15:37:57 -----
进程1565的详细日志
----- end 1565 ---------- pid xxx at xxxx-xx-xx xx:xx:xx -----
进程xxx的详细日志
----- end xxx -----
————————————————
从上面的格式我们可以看出,文件以每个进程分块,列出了每个进程下面各个线程的活动状态,同时,一般第一个进程就是主进程,所以我们大多数情况下只要分析第一个进程即可.
那么,每个进程中的所展示的内容又是什么呢?我们继续展开看一下:
----- pid 12061 at 2023-04java-12 13:48:06 -----
Cmd line: com.xxx.xxx
Build fingerprint: 'TECNO/H571/TECNO-AX8:7.0/NRD90M/B-190624V299:user/release-keys'
ABI: 'arm64'
Build type: optimized/** =====================类加载信息-开始 class_linker.cc中写入，记录类加载信息===================== */
Zygote loaded classes=16108 post zygote classes=9573
Dumping registered class loaders
#0 dalvik.system.PathClassLoader: [], parent #1
#1 java.lang.BootClassLoader: [], no parent
#2 dalvik.system.PathClassLoader: [/data/app/~~vbVFUHP-Q5oukq_bLiNj0w==/com.transsnet.boomplay.lite-R3xTRHDqhXkMGO0tbfFeGw==/base.apk:/data/app/~~vbVFUHP-Q5oukq_bLiNj0w==/com.transsnet.boomplay.lite-R3xTRHDqhXkMGO0tbfFeGw==/base.apk!classes2.dex:/data/app/~~vbVFUHP-Q5oukq_bLiNj0w==/com.transsnet.boomplay.lite-R3xTRHDqhXkMGO0tbfFeGw==/base.apk!classes3.dex], parent #1
#3 dalvik.system.InMemoryDexClassLoader: [/data/user/0/com.transsnet.boomplay.lite/Anonymous-DexFile@2764641574.jar], parent #2
#4 dalvik.system.DelegateLastClassLoader: [/data/user_de/0/com.google.android.gms/app_chimera/m/00000002/DynamiteLoader.apk], parent #0
#5 dalvik.system.DelegateLastClassLoader: [/data/user_de/0/com.google.android.gms/app_chimera/m/00000000/AdsDynamite.apk], parent #2
#6 dalvik.system.InMemoryDexClassLoader: [/data/user/0/com.transsnet.boomplay.lite/Anonymous-DexFile@3764699927.jar], parent #2
#7 dalvik.system.InMemoryDexClassLoader: [/data/user/0/com.transsnet.boomplay.lite/Anonymous-DexFile@1904604828.jar], parent #2
#8 dalvik.system.PathClassLoader: [/product/app/WebViewGoogle/WebViewGoogle.apk], parent #1
#9 dalvik.system.PathClassLoader: [/product/app/TrichromeLibrary/TrichromeLibrary.apk], parent #1
#10 dalvik.system.DexClassLoader: [/data/user/0/com.transsnet.boomplay.lite/cache/1658186039475.jar], parent #2
#11 dalvik.system.DexClassLoader: [/data/user/0/com.transsnet.boomplay.lite/app_pccache/2/BDA423607FA5C8DB48E6A852040B4F20FC43D4B8/pcam.jar], parent #2
Done dumping class loaders
Classes initialized: 7610 in 6.478s
/** =====================类加载信息-结束========================================================= *//** =====================引用表-开始 intern_table.cc中写入，记录强弱引用数量===================== */
Intern table: 52569 strong; 653 weak
/** =====================引用表-结束=========================================================== *//** =====================JNI加载信息-开始 java_vm_ext.cc中写入，记录加载的so===================== */
JNI: CheckJNI is on; globals=537 (plus 272 weak)
Libraries: /data/app/com.xxx.xxx-2/lib/arm64/libxxx.so /data/app/com.xxx.xxx-2/lib/arm64/libmmkv.so /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (10)
/** =====================JNI加载信息-结束====================================================== *//** =====================java虚拟机堆状态-开始 heap.cc中写入，记录当前的内存状态===================== */
Heap: 1% free, 22MB/22MB; 75975 objects
Dumping cumulative Gc timings
Start Dumping histograms for 1 iterations for partial concurrent mark sweep
ProcessMarkStack: Sum: 13.723ms 99% C.I. 0.101ms-13.010ms Avg: 4.574ms Max: 13.036ms
MarkRootsCheckpoint: Sum: 12.257ms 99% C.I. 6.064ms-6.193ms Avg: 6.128ms Max: 6.193ms
UpdateAndMarkImageModUnionTable: Sum: 9.253ms 99% C.I. 0.772us-5675us Avg: 544.294us Max: 6044us
SweepMallocSpace: Sum: 5.684ms 99% C.I. 0.044ms-5.640ms Avg: 2.842ms Max: 5.640ms
ScanGrayAllocSpaceObjects: Sum: 4.281ms 99% C.I. 0.002ms-4.257ms Avg: 2.140ms Max: 4.279ms
UpdateAndMarkZygoteModUnionTable: Sum: 4.197ms 99% C.I. 4.197ms-4.197ms Avg: 4.197ms Max: 4.197ms
AllocSpaceClearCards: Sum: 4.094ms 99% C.I. 0.001ms-3.971ms Avg: 1.023ms Max: 4.023ms
MarkConcurrentRoots: Sum: 3.598ms 99% C.I. 0.565ms-3.025ms Avg: 1.799ms Max: 3.033ms
(Paused)ScanGrayAllocSpaceObjects: Sum: 2.214ms 99% C.I. 0.004ms-2.210ms Avg: 1.107ms Max: 2.210ms
ReMarkRoots: Sum: 1.367ms 99% C.I. 1.367ms-1.367ms Avg: 1.367ms Max: 1.367ms
MarkAllocStackAsLive: Sum: 1.293ms 99% C.I. 1.293ms-1.293ms Avg: 1.293ms Max: 1.293ms
ScanGrayImageSpaceObjects: Sum: 1.034ms 99% C.I. 0.283us-711.750us Avg: 60.823us Max: 722us
(Paused)ScanGrayImageSpaceObjects: Sum: 738us 99% C.I. 0.265us-644.750us Avg: 43.411us Max: 686us
(Paused)ProcessMarkStack: Sum: 225us 99% C.I. 225us-225us Avg: 225us Max: 225us
SweepLargeObjects: Sum: 198us 99% C.I. 198us-198us Avg: 198us Max: 198us
SweepSystemWeaks: Sum: 163us 99% C.I. 163us-163us Avg: 163us Max: 163us
BindBitmaps: Sum: 113us 99% C.I. 113us-113us Avg: 113us Max: 113us
MarkNonThreadRoots: Sum: 108us 99% C.I. 53us-55us Avg: 54us Max: 55us
EnqueueFinalizerReferences: Sum: 105us 99% C.I. 105us-105us Avg: 105us Max: 105us
ImageModUnionClearCards: Sum: 104us 99% C.I. 0.250us-39us Avg: 3.058us Max: 39us
FinishPhase: Sum: 77us 99% C.I. 77us-77us Avg: 77us Max: 77us
ProcessReferences: Sum: 59us 99% C.I. 59us-59us Avg: 59us Max: 59us
ZygoteModUnionClearCards: Sum: 57us 99% C.I. 12us-45us Avg: 28.500us Max: 45us
RevokeAllThreadLocalAllocationStacks: Sum: 51us 99% C.I. 51us-51us Avg: 51us Max: 51us
MarkingPhase: Sum: 43us 99% C.I. 43us-43us Avg: 43us Max: 43us
ReclaimPhase: Sum: 42us 99% C.I. 42us-42us Avg: 42us Max: 42us
(Paused)PausePhase: Sum: 31us 99% C.I. 31us-31us Avg: 31us Max: 31us
ProcessCards: Sum: 29us 99% C.I. 13us-16us Avg: 14.500us Max: 16us
ScanGrayZygoteSpaceObjects: Sum: 25us 99% C.I. 25us-25us Avg: 25us Max: 25us
PreCleanCards: Sum: 22us 99% C.I. 22us-22us Avg: 22us Max: 22us
SwapBitmaps: Sum: 14us 99% C.I. 14us-14us Avg: 14us Max: 14us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 13us 99% C.I. 13us-13us Avg: 13us Max: 13us
Sweep: Sum: 12us 99% C.I. 12us-12us Avg: 12us Max: 12us
MarkRoots: Sum: 4us 99% C.I. 4us-4us Avg: 4us Max: 4us
InitializePhase: Sum: 3us 99% C.I. 3us-3us Avg: 3us Max: 3us
RecursiveMark: Sum: 2us 99% C.I. 2us-2us Avg: 2us Max: 2us
SweepZygoteSpace: Sum: 1us 99% C.I. 1us-1us Avg: 1us Max: 1us
FindDefaultSpaceBitmap: Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms
partial concurrent mark sweep paused: Sum: 6.716ms 99% C.I. 6.716ms-6.716ms Avg: 6.716ms Max: 6.716ms
partial concurrent mark sweep total time: 65.237ms mean time: 65.237ms
partial concurrent mark sweep freed: 47501 objects with total size 5MB
partial concurrent mark sweep throughput: 730785/s / 78MB/s
Start Dumping histograms for 2 iterations for sticky concurrent mark sweep
FreeList: Sum: 33.813ms 99% C.I. 4us-4566us Avg: 367.532us Max: 5846us
MarkRootsCheckpoint: Sum: 29.286ms 99% C.I. 2.440ms-13.136ms Avg: 7.321ms Max: 13.198ms
ScanGrayAllocSpaceObjects: Sum: 17.030ms 99% C.I. 0.002ms-10.912ms Avg: 2.128ms Max: 11.077ms
ProcessMarkStack: Sum: 11.693ms 99% C.I. 0.001ms-6.876ms Avg: 1.461ms Max: 6.980ms
SweepArray: Sum: 9.276ms 99% C.I. 2.812ms-6.464ms Avg: 4.638ms Max: 6.464ms
MarkConcurrentRoots: Sum: 9.065ms 99% C.I. 0.010ms-6.326ms Avg: 2.266ms Max: 6.356ms
ScanGrayImageSpaceObjects: Sum: 5.890ms 99% C.I. 0.288us-1678.999us Avg: 86.617us Max: 1864us
MarkNonThreadRoots: Sum: 4.015ms 99% C.I. 0.045ms-3.775ms Avg: 1.003ms Max: 3.820ms
ReMarkRoots: Sum: 2.579ms 99% C.I. 0.575ms-2.004ms Avg: 1.289ms Max: 2.004ms
SweepSystemWeaks: Sum: 1.775ms 99% C.I. 315us-1460us Avg: 887.500us Max: 1460us
(Paused)ScanGrayAllocSpaceObjects: Sum: 979us 99% C.I. 0.500us-883us Avg: 244.750us Max: 883us
ScanGrayZygoteSpaceObjects: Sum: 951us 99% C.I. 11us-691us Avg: 237.750us Max: 692us
MarkingPhase: Sum: 499us 99% C.I. 226us-273us Avg: 249.500us Max: 273us
AllocSpaceClearCards: Sum: 457us 99% C.I. 0.333us-202us Avg: 57.125us Max: 202us
BindBitmaps: Sum: 330us 99% C.I. 108us-222us Avg: 165us Max: 222us
ImageModUnionClearCards: Sum: 258us 99% C.I. 0.253us-59us Avg: 3.794us Max: 59us
ResetStack: Sum: 231us 99% C.I. 87us-144us Avg: 115.500us Max: 144us
EnqueueFinalizerReferences: Sum: 171us 99% C.I. 20us-151us Avg: 85.500us Max: 151us
ProcessReferences: Sum: 125us 99% C.I. 15us-110us Avg: 62.500us Max: 110us
RevokeAllThreadLocalAllocationStacks: Sum: 121us 99% C.I. 37us-84us Avg: 60.500us Max: 84us
ReclaimPhase: Sum: 111us 99% C.I. 26us-85us Avg: 55.500us Max: 85us
(Paused)PausePhase: Sum: 109us 99% C.I. 35us-74us Avg: 54.500us Max: 74us
FinishPhase: Sum: 82us 99% C.I. 32us-50us Avg: 41us Max: 50us
ZygoteModUnionClearCards: Sum: 73us 99% C.I. 12us-27us Avg: 18.250us Max: 27us
(Paused)ScanGrayImageSpaceObjects: Sum: 68us 99% C.I. 0.250us-21us Avg: 2us Max: 21us
InitializePhase: Sum: 63us 99% C.I. 16us-47us Avg: 31.500us Max: 47us
PreCleanCards: Sum: 51us 99% C.I. 23us-28us Avg: 25.500us Max: 28us
(Paused)ProcessMarkStack: Sum: 45us 99% C.I. 1us-44us Avg: 22.500us Max: 44us
SwapBitmaps: Sum: 29us 99% C.I. 10us-19us Avg: 14.500us Max: 19us
ForwardSoftReferences: Sum: 20us 99% C.I. 3us-17us Avg: 10us Max: 17us
(Paused)ScanGrayZygoteSpaceObjects: Sum: 18us 99% C.I. 7us-11us Avg: 9us Max: 11us
MarkRoots: Sum: 11us 99% C.I. 5us-6us Avg: 5.500us Max: 6us
UnBindBitmaps: Sum: 10us 99% C.I. 3us-7us Avg: 5us Max: 7us
SwapStacks: Sum: 4us 99% C.I. 2us-2us Avg: 2us Max: 2us
RecordFree: Sum: 3us 99% C.I. 1us-2us Avg: 1.500us Max: 2us
FindDefaultSpaceBitmap: Sum: 2us 99% C.I. 1us-1us Avg: 1us Max: 1us
PreSweepingGcVerification: Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms
sticky concurrent mark sweep paused: Sum: 4.504ms 99% C.I. 2.035ms-2.469ms Avg: 2.252ms Max: 2.469ms
sticky concurrent mark sweep total time: 129.294ms mean time: 64.647ms
sticky concurrent mark sweep freed: 91166 objects with total size 6MB
sticky concurrent mark sweep throughput: 706713/s / 51MB/s
Total time spent in GC: 194.531ms
Mean GC size throughput: 51MB/s
Mean GC object throughput: 712498 objects/s
/** 2.2 内存信息* start/
Total number of allocations 214578
Total bytes allocated 32MB
Total bytes freed 10MB
Free memory 335KB
Free memory until GC 335KB
Free memory until OOME 361MB
Total memory 22MB
Max memory 384MB
/** 2.2 内存信息* end/
Zygote space size 1340KB
Total mutator paused time: 11.220ms
Total time waiting for GC to complete: 3.077us
Total GC count: 3
Total GC time: 194.531ms
Total blocking GC count: 0
Total blocking GC time: 0
Histogram of native allocation 0:1038,128:379,256:105,384:160,640:1,896:16,1152:2 bucket size 128
Histogram of native free 0:156,64:133,192:351,256:38,448:90,640:1 bucket size 64
/** =====================java虚拟机堆状态-结束====================================================== *//** =====================OTA文件记录-开始 oat_file_manager.cc中写入，记录当前使用到的OTA文件===================== */
/data/user_de/0/com.google.android.gms/app_chimera/m/0000030c/oat/arm64/MeasurementDynamite.odex: speed
/data/user/0/com.xxx.xxx/app_optimized/audience_network.dex: speed
/system/framework/oat/arm64/com.android.location.provider.odex: speed
/system/framework/oat/arm64/com.android.media.remotedisplay.odex: speed
/data/app/com.google.android.gms-2/oat/arm64/base.odex: interpret-only
/data/user_de/0/com.google.android.gms/app_chimera/m/00000307/oat/arm64/DynamiteLoader.odex: speed
/data/user_de/0/com.google.android.gms/app_chimera/m/000002ee/oat/arm64/dl-AdsFdrDynamite.integ_230500000000000.odex: speed
/data/app/com.xxx.xxx-2/oat/arm64/base.odex: interpret-only
/** =====================OTA文件记录-结束===================================================================== *//** =====================JIT信息记录-开始 jit.cc中写入，记录JIT的信息===================== */
Current JIT code cache size: 17KB
Current JIT data cache size: 20KB
Current JIT capacity: 64KB
Current number of JIT code cache entries: 16
Total number of JIT compilations: 16
Total number of JIT compilations for on stack replacement: 0
Total number of deoptimizations: 0
Total number of JIT code cache collections: 0
Memory used for stack maps: Avg: 675B Max: 2992B Min: 64B
Memory used for compiled code: Avg: 1081B Max: 2648B Min: 176B
Memory used for profiling info: Avg: 274B Max: 1040B Min: 32B
Start Dumping histograms for 16 iterations for JIT timings
Compiling: Sum: 512.109ms 99% C.I. 3.640ms-96.064ms Avg: 32.006ms Max: 96.425ms
TrimMaps: Sum: 12.116ms 99% C.I. 41us-5108us Avg: 757.250us Max: 5295us
Done Dumping histograms
Memory used for compilation: Avg: 346KB Max: 959KB Min: 77KB
ProfileSaver total_bytes_written=0
ProfileSaver total_number_of_writes=0
ProfileSaver total_number_of_code_cache_queries=0
ProfileSaver total_number_of_skipped_writes=0
ProfileSaver total_number_of_failed_writes=0
ProfileSaver total_ms_of_sleep=2000
ProfileSaver total_ms_of_work=0
ProfileSaver total_number_of_foreign_dex_marks=2
ProfileSaver max_number_profile_entries_cached=19
ProfileSaver total_number_of_hot_spikes=0
ProfileSaver total_number_of_wake_ups=0
/** =====================JIT信息记录-结束================================================ *//** =====================ART信息指标-开始 metrics_common.cc中写入，记录ART虚拟机的一些关键指标===================== */
*** ART internal metrics ***Metadata:timestamp_since_start_ms: 19952Metrics:ClassLoadingTotalTime: count = 17358ClassVerificationTotalTime: count = 15303ClassVerificationCount: count = 28WorldStopTimeDuringGCAvg: count = 0YoungGcCount: count = 0FullGcCount: count = 0TotalBytesAllocated: count = 2349168TotalGcCollectionTime: count = 0YoungGcThroughputAvg: count = 0FullGcThroughputAvg: count = 0YoungGcTracingThroughputAvg: count = 0FullGcTracingThroughputAvg: count = 0JitMethodCompileTotalTime: count = 28492JitMethodCompileCount: count = 39YoungGcCollectionTime: range = 0...60000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0FullGcCollectionTime: range = 0...60000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0YoungGcThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0FullGcThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0YoungGcTracingThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0FullGcTracingThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
*** Done dumping ART internal metrics ***
/** =====================ART信息指标-结束====================================================================== *//** =====================线程信息-开始 thread_list.cc中写入，记录当前进程的线程信息============================== */
suspend all histogram: Sum: 2.785ms 99% C.I. 4us-1964.800us Avg: 278.500us Max: 2044us
DALVIK THREADS (71):
"Signal Catcher" daemon prio=5 tid=3 Runnable| group="system" sCount=0 dsCount=0 obj=0x12d555e0 self=0x7a8d897400| sysTid=12067 nice=0 cgrp=default sched=0/0 handle=0x7a8cd04450| state=R schedstat=( 53844613 20052004 79 ) utm=2 stm=2 core=0 HZ=100| stack=0x7a8cc0a000-0x7a8cc0c000 stackSize=1005KB| held mutexes= "mutator lock"(shared held)native: #00 pc 000000000047c0fc /system/lib64/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+220)native: #01 pc 000000000047c0f8 /system/lib64/libart.so (_ZN3art15DumpNativeStackERNSt3__113basic_ostreamIcNS0_11char_traitsIcEEEEiP12BacktraceMapPKcPNS_9ArtMethodEPv+216)native: #02 pc 000000000045027c /system/lib64/libart.so (_ZNK3art6Thread9DumpStackERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEbP12BacktraceMap+480)native: #03 pc 0000000000467de8 /system/lib64/libart.so (_ZN3art14DumpCheckpoint3RunEPNS_6ThreadE+832)native: #04 pc 00000000004600d4 /system/lib64/libart.so (_ZN3art10ThreadList13RunCheckpointEPNS_7ClosureE+476)native: #05 pc 000000000045fcc4 /system/lib64/libart.so (_ZN3art10ThreadList4DumpERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEEb+848)native: #06 pc 000000000045f930 /system/lib64/libart.so (_ZN3art10ThreadList14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+804)native: #07 pc 000000000043b8c4 /system/lib64/libart.so (_ZN3art7Runtime14DumpForSigQuitERNSt3__113basic_ostreamIcNS1_11char_traitsIcEEEE+344)native: #08 pc 0000000000441f44 /system/lib64/libart.so (_ZN3art13SignalCatcher13HandleSigQuitEv+2096)native: #09 pc 0000000000440aec /system/lib64/libart.so (_ZN3art13SignalCatcher3RunEPv+480)native: #10 pc 000000000006a31c /system/lib64/libc.so (_ZL15__pthread_startPv+208)native: #11 pc 000000000001db28 /system/lib64/libc.so (__start_thread+16)(no managed stack frames)"main" prio=5 tid=1 Blocked| group="main" sCount=1 dsCount=0 obj=0x75bc7c50 self=0x7a8d896a00| sysTid=12061 nice=0 cgrp=default sched=0/0 handle=0x7a91e23a98| state=S schedstat=( 401196933 229090000 643 ) utm=29 stm=10 core=4 HZ=100| stack=0x7ff9366000-0x7ff9368000 stackSize=8MB| held mutexes=at android.app.SystemServiceRegistry$CachedServiceFetcher.getService(SystemServiceRegistry.java:929)- waiting to lock <0x077d5864> (a java.lang.Object[]) held by thread 23at android.app.SystemServiceRegistry.getSystemService(SystemServiceRegistry.java:886)at android.app.ContextImpl.getSystemService(ContextImpl.java:1524)at android.content.ContextWrapper.getSystemService(ContextWrapper.java:659)at android.view.TouchScreenHelper.updateDisplayInfo(TouchScreenHelper.java:323)at android.view.TouchScreenHelper.init(TouchScreenHelper.java:149)at android.view.TouchScreenHelper.<init>(TouchScreenHelper.java:87)at android.view.WindowManagerGlobal.getTouchScreenHelper(WindowManagerGlobal.java:173)- locked <0x02a54acd> (a java.lang.Class<android.view.WindowManagerGlobal>)at com.android.internal.policy.DecorView.<init>(DecorView.java:290)at com.android.internal.policy.PhoneWindow.generateDecor(PhoneWindow.java:2376)at com.android.internal.policy.PhoneWindow.installDecor(PhoneWindow.java:2730)at com.android.internal.policy.PhoneWindow.getDecorView(PhoneWindow.java:2085)at com.xxx.common.base.XxxBaseActivity.toggleTranslucent(XxxBaseActivity.java:37)at com.xxx.common.base.XxxBaseActivity.onCreate(XxxBaseActivity.java:20)at com.xxx.xxx.guide.ControllerActivity.onCreate(ControllerActivity.java:174)at android.app.Activity.performCreate(Activity.java:6734)at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1118)at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2681)at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2793)at android.app.ActivityThread.-wrap12(ActivityThread.java:-1)at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1527)at android.os.Handler.dispatchMessage(Handler.java:110)at android.os.Looper.loop(Looper.java:203)at android.app.ActivityThread.main(ActivityThread.java:6301)at java.lang.reflect.Method.invoke!(Native method)at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1094)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:955)"RxCachedThreadScheduler-1" daemon prio=5 tid=23 Blocked| group="main" sCount=1 dsCount=0 obj=0x12f61af0 self=0x7a8211fa00| sysTid=12096 nice=0 cgrp=default sched=0/0 handle=0x7a68c66450| state=S schedstat=( 164816616 182495075 396 ) utm=13 stm=2 core=7 HZ=100| stack=0x7a68b64000-0x7a68b66000 stackSize=1037KB| held mutexes=at android.view.WindowManagerGlobal.getInstance(WindowManagerGlobal.java:182)- waiting to lock <0x02a54acd> (a java.lang.Class<android.view.WindowManagerGlobal>) held by thread 1at android.view.WindowManagerImpl.<init>(WindowManagerImpl.java:58)at android.view.WindowManagerImpl.<init>(WindowManagerImpl.java:65)at android.app.SystemServiceRegistry$50.createService(SystemServiceRegistry.java:599)at android.app.SystemServiceRegistry$50.createService(SystemServiceRegistry.java:598)at android.app.SystemServiceRegistry$CachedServiceFetcher.getService(SystemServiceRegistry.java:933)- locked <0x077d5864> (a java.lang.Object[])at android.app.SystemServiceRegistry.getSystemService(SystemServiceRegistry.java:886)at android.app.ContextImpl.getSystemService(ContextImpl.java:1524)at android.content.ContextWrapper.getSystemService(ContextWrapper.java:659)at me.jessyan.autosize.utils.ScreenUtils.getScreenSize(ScreenUtils.java:62)at me.jessyan.autosize.AutoSizeConfig.init(AutoSizeConfig.java:247)at me.jessyan.autosize.AutoSizeConfig.init(AutoSizeConfig.java:205)at me.jessyan.autosize.AutoSize.checkAndInit(AutoSize.java:84)at com.xxx.common.base.XxxApplicationInitor.initAutoSize(MusicApplicationInitor.java:404)at com.xxx.common.base.XxxApplicationInitor.thirdSDKInit(MusicApplicationInitor.java:414)at com.xxx.common.base.XxxApplicationInitor.preInit(MusicApplicationInitor.java:438)at com.xxx.common.base.XxxApplicationInitor.access$800(MusicApplicationInitor.java:109)at com.xxx.common.base.XxxApplicationInitor$10.subscribe(MusicApplicationInitor.java:231)at io.reactivex.internal.operators.observable.ObservableCreate.subscribeActual(ObservableCreate.java:40)at io.reactivex.Observable.subscribe(Observable.java:12284)at io.reactivex.internal.operators.observable.ObservableSubscribeOn$SubscribeTask.run(ObservableSubscribeOn.java:96)at io.reactivex.Scheduler$DisposeTask.run(Scheduler.java:578)at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66)at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57)at java.util.concurrent.FutureTask.run(FutureTask.java:237)at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:272)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)at java.lang.Thread.run(Thread.java:761)"Binder:1002_1" prio=5 tid=7 Native| group="main" sCount=1 dsCount=0 obj=0x12c01940 self=0x7a8d8c3400| sysTid=1020 nice=0 cgrp=default sched=0/0 handle=0x7a869be450| state=S schedstat=( 19616954905 44253949137 66794 ) utm=1314 stm=647 core=1 HZ=100| stack=0x7a868c4000-0x7a868c6000 stackSize=1005KB| held mutexes=kernel: (couldn't read /proc/self/task/1020/stack)native: #00 pc 000000000006c840 /system/lib64/libc.so (__ioctl+4)native: #01 pc 000000000001fb60 /system/lib64/libc.so (ioctl+140)native: #02 pc 0000000000055698 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+264)native: #03 pc 00000000000557fc /system/lib64/libbinder.so (_ZN7android14IPCThreadState20getAndExecuteCommandEv+24)native: #04 pc 0000000000055f4c /system/lib64/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+72)native: #05 pc 00000000000739f8 /system/lib64/libbinder.so (???)native: #06 pc 0000000000012598 /system/lib64/libutils.so (_ZN7android6Thread11_threadLoopEPv+272)native: #07 pc 00000000000a2618 /system/lib64/libandroid_runtime.so (_ZN7android14AndroidRuntime15javaThreadShellEPv+128)native: #08 pc 000000000006a31c /system/lib64/libc.so (_ZL15__pthread_startPv+208)native: #09 pc 000000000001db28 /system/lib64/libc.so (__start_thread+16)(no managed stack frames).../** =====================线程信息-结束============================================================================*/从上面文件中,我们能看到了记录一个进程中活动信息的所有内容,并且内容十分丰富繁多,原文件更大,我做了部分删减,这样能更加清晰的看出整个进程的所展示信息的框架,其中最重要的就是线程的活动状态,以及每个线程的堆栈信息.
下面我们对我们的主线程,也就是main线程的具体参数,作出解释.
具体解释如下：
| 所在行 | 内容 | 解释 |
|---|---|---|
| 1 | “main” | 线程名 |
| 1 | prio=5 | 线程优先级 |
| 1 | tid=1 | 线程标识符 |
| 1 | Blocked | 线程状态,表明当前线程处于阻塞状态,其它状态还有,waiting:线程等待状态,也就是挂起状态runnalbe:线程运行状态native:native是native中的线程状态,表明正在实行jni本地函数，对应java中runnable |
| 2 | group=“main” | 线程所属的线程组 |
| 2 | sCount=1 | 程被正常挂起的次数 |
| 2 | dsCount=0 | 线程因调试而挂起次数 |
| 2 | flags=1 | |
| 2 | obj=0x75c4db98 | 线程的Java对象的地址 |
| 2 | self=0x7b08e14c00 | 线程本身的地址 |
| 3 | sysTid=2468 | Linux下的内核线程id |
| 3 | nice=0 | 线程的调度优先级 |
| 3 | cgrp=default | 调度属组 |
| 3 | sched=0/0 | 线程的调度策略和优先级 |
| 3 | handle=0x7b8e933548 | 线程的处理函数地址 |
| 4 | state=S | 调度状态 |
| 4 | schedstat=( 562066147 3061697256 542 ) | 执行时间记录：三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度 |
| 4 | utm=31 | 用户态CPU占用次数，由于频率是100，则占用31次就等于31*10ms=310ms |
| 4 | stm=24 | 内核态CPU占用次数 |
| 4 | core=2 | 最后执行这个线程的CPU核序号 |
| 4 | HZ=100 | 运行频率，一秒100次 |
| 5 | stack=0x7fe841d000-0x7fe841f000 | 虚拟机栈地址 |
| 5 | stackSize=8MB | 虚拟机栈大小 |
| 6 | at android.os.BinderProxy.transactNative(Native method) at android.os.BinderProxy.transact(Binder.java:1127) | 此时采集到的APP对应线程的对应状态,也就是当时代码所执行的位置,这个信息对我们来说尤其重要,是我们分析anr的关键依据. |
上表中以主线程为例,对线程的每个参数都做出了解释,下面的子线程也同样适用.读懂了每个线程中各个参数的含义,那么最需要关心的是什么呢?
答案就是线程的状态,以及线程下打印出来对应的堆栈代码信息.线程状态可以帮助我们判断anr发生在线程层面的原因,堆栈信息可以帮我我们分析anr发生的具体代码位置.
其中线程常见状态解释如下:
- Blocked状态
也就是阻塞状态,一般主线程发生blocked,说明它在等待获取监视器锁（synchronized 锁）时，如果锁被其他线程占用，就会进入Blocked状态。示例如下:
"main" tid=1 systid=17151 blocked | waiting to lock <0x05dfb3bd> (java.lang.Object) held by thread 46at android.app.ContextImpl.getExternalCacheDirs(ContextImpl.java:836)at android.content.ContextWrapper.getExternalCacheDirs(ContextWrapper.java:311)at androidx.core.content.ContextCompat$Api19Impl.getExternalCacheDirs(ContextCompat.java:840)at androidx.core.content.ContextCompat.getExternalCacheDirs(ContextCompat.java:459)at androidx.core.content.FileProvider.parsePathStrategy(FileProvider.java:696)at androidx.core.content.FileProvider.getPathStrategy(FileProvider.java:635)at androidx.core.content.FileProvider.attachInfo(FileProvider.java:416)at android.app.ActivityThread.installProvider(ActivityThread.java:7673)at android.app.ActivityThread.installContentProviders(ActivityThread.java:7209)at android.app.ActivityThread.handleBindApplication(ActivityThread.java:7121)at android.app.ActivityThread.access$1600(ActivityThread.java:268)at android.app.ActivityThread$H.handleMessage(ActivityThread.java:2056)at android.os.Handler.dispatchMessage(Handler.java:106)at android.os.Looper.loop(Looper.java:268)at android.app.ActivityThread.main(ActivityThread.java:8107)at java.lang.reflect.Method.invoke(Method.java)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:627)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:997)
- Waiting状态
线程在等待其他线程显式地通知或中断时，会进入Waiting状态。
当线程调用Object.wait()、Thread.join()或类似的方法时，线程会进入Waiting状态，等待其他线程的通知。示例如下:
"main" prio=5 tid=1 Waiting| group="main" sCount=1 dsCount=0 flags=1 obj=0x70df6868 self=0xa7c3de00| sysTid=8565 nice=0 cgrp=default sched=1073741825/1 handle=0xa8222dc0| state=S schedstat=( 421005565 19181973 433 ) utm=25 stm=16 core=2 HZ=100| stack=0xbe132000-0xbe134000 stackSize=8192KB| held mutexes=at b.a.b.c.a.l.v(:1)- waiting on <0x077aff1b> (a java.lang.Class<b.a.b.c.a.l>)at b.a.b.c.f.b.e(:6)at b.a.b.c.a.k.c(:60)at b.a.b.c.a.k.a(:6)at b.a.b.c.a.k.<clinit>(:1)at com.xxx.storage.cache.g1.V(:2)at com.xxx.storage.cache.q1.a(:20)at com.xxx.biz.remote.j.i(:113)at com.xxx.biz.remote.j.f(:6)at com.transsnet.xxx.lite.service.PlayerService$m.a(:5)at com.transsnet.xxx.lite.service.PlayerService$m.onChanged(:1)at com.jeremyliao.liveeventbus.LiveEventBus$ObserverWrapper.onChanged(LiveEventBus.java:3)at androidx.lifecycle.LiveData.considerNotify(LiveData.java:6)at androidx.lifecycle.LiveData.dispatchingValue(LiveData.java:8)at androidx.lifecycle.LiveData.setValue(LiveData.java:4)at androidx.lifecycle.MutableLiveData.setValue(MutableLiveData.java:1)at com.jeremyliao.liveeventbus.LiveEventBus$LiveEvent.postInternal(LiveEventBus.java:1)at com.jeremyliao.liveeventbus.LiveEventBus$LiveEvent.access$1800(LiveEventBus.java:1)at com.jeremyliao.liveeventbus.LiveEventBus$LiveEvent$PostValueTask.run(LiveEventBus.java:1)at android.os.Handler.handleCallback(Handler.java:883)at android.os.Handler.dispatchMessage(Handler.java:100)at android.os.Looper.loop(Looper.java:214)at android.app.ActivityThread.main(ActivityThread.java:7669)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:590)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:936)
这里需要区分一下Blocked和Waiting状态的区别
-
BLOCKED 状态表示线程在等待获取监视器锁，它可能是由于同步块或同步方法的争用导致的。
-
WAITING 状态表示线程在等待其他线程的通知或中断，它可能是由于调用了 wait()、join() 等方法导致的。
这两种状态都属于线程的阻塞状态，但产生的原因和等待的条件是不同的。BLOCKED 状态是由于争夺锁而导致的，而 WAITING 状态是由于线程主动等待的情况。
- Runnalbe状态
Runnable,显而易见,表示线程正在运行,示例如下:
"main" prio=5 tid=1 Runnable| group="main" sCount=0 dsCount=0 flags=0 obj=0x722c7448 self=0xb0f3de00| sysTid=30043 nice=0 cgrp=default sched=1073741825/1 handle=0xb1539dc0| state=R schedstat=( 6367575122 32733935 3055 ) utm=565 stm=70 core=0 HZ=100| stack=0xbe581000-0xbe583000 stackSize=8192KB| held mutexes= "mutator lock"(shared held)native: #00 pc 00303e8b /apex/com.android.runtime/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+78)native: #01 pc 003af52b /apex/com.android.runtime/lib/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+358)native: #02 pc 003abb73 /apex/com.android.runtime/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+34)native: #03 pc 003c4ccb /apex/com.android.runtime/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+606)native: #04 pc 003aff61 /apex/com.android.runtime/lib/libart.so (art::Thread::RunCheckpointFunction()+128)native: #05 pc 0041ff45 /apex/com.android.runtime/lib/libart.so (art::JniMethodFastEnd(unsigned int, art::Thread*)+40)at java.lang.System.arraycopy(Native method)at d.a.i.put(:16)at com.bumptech.glide.util.CachedHashCodeArrayMap.put(CachedHashCodeArrayMap.java:2)at com.bumptech.glide.request.BaseRequestOptions.transform(BaseRequestOptions.java:23)at com.bumptech.glide.request.BaseRequestOptions.transform(BaseRequestOptions.java:15)at com.bumptech.glide.request.BaseRequestOptions.optionalTransform(BaseRequestOptions.java:4)at com.bumptech.glide.request.BaseRequestOptions.scaleOnlyTransform(BaseRequestOptions.java:3)at com.bumptech.glide.request.BaseRequestOptions.optionalScaleOnlyTransform(BaseRequestOptions.java:1)at com.bumptech.glide.request.BaseRequestOptions.optionalFitCenter(BaseRequestOptions.java:1)at com.xxx.util.glide.b.N(:1)at com.xxx.util.glide.b.optionalFitCenter(:1)at com.bumptech.glide.RequestBuilder.into(RequestBuilder.java:22)at e.a.b.b.b.e(:46)at e.a.b.b.b.g(:2)at com.xxx.kit.function.HomeLastPlayedView.f(HomeLastPlayedView.java:4)at com.xxx.kit.function.HomeLastPlayedView.b(HomeLastPlayedView.java:29)at com.xxx.kit.function.HomeLastPlayedView.g(HomeLastPlayedView.java:12)at com.xxx.ui.home.c.n1.A1(:4)at com.xxx.ui.home.c.n1.z1(:5)at com.xxx.ui.home.c.n1.D(:1)at com.chad.library.adapter.base.m.n0(:4)at com.chad.library.adapter.base.m.o0(:2)at com.chad.library.adapter.base.m.onBindViewHolder(:2)at androidx.recyclerview.widget.RecyclerView$h.bindViewHolder(:8)...省略View绘制流程堆栈...at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1840)at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:7937)at android.view.Choreographer$CallbackRecord.run(Choreographer.java:980)at android.view.Choreographer.doCallbacks(Choreographer.java:804)at android.view.Choreographer.doFrame(Choreographer.java:739)at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:965)at android.os.Handler.handleCallback(Handler.java:883)at android.os.Handler.dispatchMessage(Handler.java:100)at android.os.Looper.loop(Looper.java:264)at android.app.ActivityThread.main(ActivityThread.java:7605)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
- native状态
native状态其实就是对应java中的Runnable状态,它表明正在执行native代码,也就是通过jni执行底层C语言方法块
"main" prio=5 tid=1 Native| group="main" sCount=1 dsCount=0 flags=1 obj=0x71356448 self=0xad23de00| sysTid=5281 nice=0 cgrp=default sched=1073741825/1 handle=0xad781dc0| state=S schedstat=( 513647352614 2827621143 157445 ) utm=45497 stm=5867 core=0 HZ=100| stack=0xbe6c9000-0xbe6cb000 stackSize=8192KB| held mutexes=kernel: (couldn't read /proc/self/task/5281/stack)native: #00 pc 0005a16c /apex/com.android.runtime/lib/bionic/libc.so (syscall+28)native: #01 pc 0005f58d /apex/com.android.runtime/lib/bionic/libc.so (__futex_wait_ex(void volatile*, bool, int, bool, timespec const*)+88)native: #02 pc 000a58ad /apex/com.android.runtime/lib/bionic/libc.so (pthread_cond_wait+32)native: #03 pc 0004dd89 /system/lib/libc++.so (std::__1::condition_variable::wait(std::__1::unique_lock<std::__1::mutex>&)+8)native: #04 pc 0004fbfb /system/lib/libc++.so (std::__1::__assoc_sub_state::copy()+54)native: #05 pc 0004fdd1 /system/lib/libc++.so (std::__1::future<void>::get()+10)native: #06 pc 0034e119 /system/lib/libhwui.so (android::uirenderer::renderthread::RenderProxy::destroyHardwareResources()+144)at android.graphics.HardwareRenderer.nDestroyHardwareResources(Native method)at android.graphics.HardwareRenderer.clearContent(HardwareRenderer.java:505)at android.view.ThreadedRenderer.destroyHardwareResources(ThreadedRenderer.java:456)at android.view.ViewRootImpl.destroyHardwareRenderer(ViewRootImpl.java:7503)at android.view.ViewRootImpl.dispatchDetachedFromWindow(ViewRootImpl.java:4362)at android.view.ViewRootImpl.doDie(ViewRootImpl.java:7424)- locked <0x02d4ecb5> (a android.view.ViewRootImpl)at android.view.ViewRootImpl.die(ViewRootImpl.java:7397)at android.view.WindowManagerGlobal.removeViewLocked(WindowManagerGlobal.java:490)at android.view.WindowManagerGlobal.removeView(WindowManagerGlobal.java:428)- locked <0x0dc61f4a> (a java.lang.Object)at android.view.WindowManagerImpl.removeViewImmediate(WindowManagerImpl.java:126)at android.app.Dialog.dismissDialog(Dialog.java:389)at android.app.Dialog.dismiss(Dialog.java:371)at com.xxx.kit.function.CommonDialog$35.onClick(CommonDialog.java:957)at android.view.View.performClick(View.java:7156)at android.view.View.performClickInternal(View.java:7129)at android.view.View.onKeyUp(View.java:14212)at android.view.KeyEvent.dispatch(KeyEvent.java:2833)at android.view.View.dispatchKeyEvent(View.java:13398)at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1921)at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1931)at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1931)at android.view.ViewGroup.dispatchKeyEvent(ViewGroup.java:1931)at com.android.internal.policy.DecorView.superDispatchKeyEvent(DecorView.java:457)at com.android.internal.policy.PhoneWindow.superDispatchKeyEvent(PhoneWindow.java:1849)at android.app.Dialog.dispatchKeyEvent(Dialog.java:825)at com.android.internal.policy.DecorView.dispatchKeyEvent(DecorView.java:371)at android.view.ViewRootImpl$ViewPostImeInputStage.processKeyEvent(ViewRootImpl.java:5640)at android.view.ViewRootImpl$ViewPostImeInputStage.onProcess(ViewRootImpl.java:5503)at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:5006)at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:5059)at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:5025)at android.view.ViewRootImpl$AsyncInputStage.forward(ViewRootImpl.java:5165)at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:5033)at android.view.ViewRootImpl$AsyncInputStage.apply(ViewRootImpl.java:5222)at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:5006)at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:5059)at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:5025)at android.view.ViewRootImpl$InputStage.apply(ViewRootImpl.java:5033)at android.view.ViewRootImpl$InputStage.deliver(ViewRootImpl.java:5006)at android.view.ViewRootImpl$InputStage.onDeliverToNext(ViewRootImpl.java:5059)at android.view.ViewRootImpl$InputStage.forward(ViewRootImpl.java:5025)at android.view.ViewRootImpl$AsyncInputStage.forward(ViewRootImpl.java:5198)at android.view.ViewRootImpl$ImeInputStage.onFinishedInputEvent(ViewRootImpl.java:5363)at android.view.inputmethod.InputMethodManager$PendingEvent.run(InputMethodManager.java:3064)at android.view.inputmethod.InputMethodManager.invokeFinishedInputEventCallback(InputMethodManager.java:2607)at android.view.inputmethod.InputMethodManager.finishedInputEvent(InputMethodManager.java:2598)at android.view.inputmethod.InputMethodManager$ImeInputEventSender.onInputEventFinished(InputMethodManager.java:3041)at android.view.InputEventSender.dispatchInputEventFinished(InputEventSender.java:143)at android.os.MessageQueue.nativePollOnce(Native method)at android.os.MessageQueue.next(MessageQueue.java:336)at android.os.Looper.loop(Looper.java:215)at android.app.ActivityThread.main(ActivityThread.java:7605)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:980)
了解完了线程的各个状态,我们就对整个anr文件有了一定了解和分析能力了.我们只要再结合堆栈信息,相信我们一定能找我anr所在位置.
接下来我们以上次发生的问题为例,来分析一下,anr发生的原因和位置.
我们可以看到,主线程当前正处于Rnnable状态,说明主线程代码正在执行,并没有被其它线程阻塞,那它为什么会发生anr呢?
很容易想到,主线程中肯定是有什么耗时操作影响了其他UI的绘制以及触摸事件的响应.
这里我们可以想到的耗时操作有.
-
有耗时的遍历
-
有IO操作
-
有十分频繁的某个UI的绘制
那我们根据主线程中的堆栈信息可以知道,anr发生的时候,ViewPager正在执行populate计算,这个方法如果有阅读过源码经验的同学,肯定知道它是帮助ViewPager在滑动或者切换时候更新ViewPager左右缓存用的,虽然这里我们没有看到堆栈信息里面有我们自己写的代码,但是我们可以借助debug工具,断点到calculatePageOffsets这个方法,从这个方法里我们根据断点信息,找到了我们代码中可能出现anr位置,如下:
从上面的断点我们可以看到,JDAutoImagerAdapter调用了getCount方法,JDAutoImagerAdapter这个方法是我们自己写的类,而且我们重写了这个类,那我再看一下,我们是如何重写的
我们看到我们重写的时候我们把count设置了int最大值,我们把count设置成了这么大,那有没有可能我们设置成了最大值后,在populate方法中产生一个耗时的循环导致anr的呢,事实的确如此.最终导致anr的原因就是主线程卡在了populate中的一个for循环中,它需要循环的次数是int的最大值除以2,相当于5亿多次.具体ViewPager为什么会这么设置,又是怎么导致这样的anr产生的,这里就不再展开了.毕竟这篇文章主要是为了向大家介绍定位anr的方法.有兴趣的同学可以看一下下面链接的文档进行深究 https://www.jianshu.com/p/d465307accff
从这里我们最终可以确定导致此次anr事件的原因是主线程中有耗时的遍历导致的.至此,整个anr过程分析完成.
4.如何避免anr的产生
了解完了如何定位和分析anr.当然,未雨绸缪才是我们最该做的事情,因此了解如何高效编码才能降低我们产生anr的概率才是我们需要长期努力的方向.下面给予一些建议:
-
绝对不要在主线程上进行复杂耗时的操作，比如说发送接收网络数据、进行大量计算、操作数据库、读写文件等，统统采用异步操作
-
Service中的耗时操作最好也是采用异步任务
-
在设计及代码编写阶段避免出现出现死锁、死循环等不恰当情况
-
使用一些避免、检测ANR的工具，比如:
StrictMode：用来检测代码中是否存在违规操作的工具类(检测主线程是否存在耗时操作)
BlockCanary：用来监控应用主线程的卡顿
