Android ANR Trace日志阅读分析技巧

什么是Trace日志

Trace日志是指ANR目录下的一份txt文件

 adb pull /data/anr/traces.txt

Trace日志有什么用

分析应用ANR无响应的问题，

Trace怎么用

Cmd line: com.xx
ABI: arm
Build type: optimized
Zygote loaded classes=3682 post zygote classes=3750
Intern table: 53619 strong; 1992 weak
JNI: CheckJNI is off; globals=889 (plus 1 weak)
Libraries: /system/lib/libandroid.so /system/lib/libaudioeffect_jni.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/librs_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so /system/priv-app/com.xx/lib/arm/liball-in-one.so /system/priv-app/com.xx/lib/arm/libeffect_proxy.so /system/priv-app/com.xx/lib/arm/libhaierjniSystemUtils.so /system/priv-app/com.xx/lib/arm/libjcore216.so /system/priv-app/com.xx/lib/arm/libpl_droidsonroids_gif.so libjavacore.so (15)
Heap: 1% free, 23MB/23MB; 245425 objects
Dumping cumulative Gc timings
Start Dumping histograms for 11 iterations for concurrent mark sweep
ProcessMarkStack:        Sum: 121.875ms 99% C.I. 0.003ms-29.281ms Avg: 3.693ms Max: 30.497ms
UpdateAndMarkImageModUnionTable:        Sum: 27.838ms 99% C.I. 0.781ms-6.128ms Avg: 2.530ms Max: 6.128ms
MarkConcurrentRoots:        Sum: 17.482ms 99% C.I. 4us-2595.500us Avg: 794.636us Max: 2670us
SweepMallocSpace:        Sum: 6.778ms 99% C.I. 3us-2167us Avg: 308.090us Max: 2183us
MarkRootsCheckpoint:        Sum: 2.782ms 99% C.I. 38us-867.499us Avg: 126.454us Max: 932us
ScanGrayAllocSpaceObjects:        Sum: 2.776ms 99% C.I. 0.392us-916us Avg: 126.181us Max: 916us
ImageModUnionClearCards:        Sum: 2.174ms 99% C.I. 76us-250us Avg: 98.818us Max: 250us
ScanGrayImageSpaceObjects:        Sum: 1.710ms 99% C.I. 89us-802us Avg: 155.454us Max: 802us
(Paused)ScanGrayImageSpaceObjects:        Sum: 1.586ms 99% C.I. 88us-667us Avg: 144.181us Max: 696us
ScanGrayZygoteSpaceObjects:        Sum: 1.564ms 99% C.I. 294us-680us Avg: 391us Max: 680us
MarkAllocStackAsLive:        Sum: 1.474ms 99% C.I. 24us-484us Avg: 134us Max: 484us
MarkNonThreadRoots:        Sum: 1.361ms 99% C.I. 13us-119us Avg: 61.863us Max: 119us
EnqueueFinalizerReferences:        Sum: 1.035ms 99% C.I. 4us-468us Avg: 94.090us Max: 468us
AllocSpaceClearCards:        Sum: 1.015ms 99% C.I. 0.289us-87us Avg: 23.068us Max: 87us
ReMarkRoots:        Sum: 909us 99% C.I. 42us-134us Avg: 82.636us Max: 134us
ZygoteModUnionClearCards:        Sum: 627us 99% C.I. 43us-232us Avg: 78.375us Max: 232us
SweepSystemWeaks:        Sum: 606us 99% C.I. 16us-230us Avg: 55.090us Max: 230us
FinishPhase:        Sum: 497us 99% C.I. 36us-63us Avg: 45.181us Max: 63us
(Paused)ScanGrayAllocSpaceObjects:        Sum: 465us 99% C.I. 0.261us-106us Avg: 21.136us Max: 106us
SweepZygoteSpace:        Sum: 373us 99% C.I. 84us-110us Avg: 93.250us Max: 110us
SwapBitmaps:        Sum: 195us 99% C.I. 10us-31us Avg: 17.727us Max: 31us
(Paused)ScanGrayZygoteSpaceObjects:        Sum: 134us 99% C.I. 33us-34us Avg: 33.500us Max: 34us
MarkingPhase:        Sum: 131us 99% C.I. 10us-18us Avg: 11.909us Max: 18us
(Paused)PausePhase:        Sum: 121us 99% C.I. 7us-20us Avg: 11us Max: 20us
ProcessCards:        Sum: 115us 99% C.I. 3us-11us Avg: 5.227us Max: 11us
PreCleanCards:        Sum: 112us 99% C.I. 8us-15us Avg: 10.181us Max: 15us
RevokeAllThreadLocalAllocationStacks:        Sum: 96us 99% C.I. 5us-14us Avg: 8.727us Max: 14us
ReclaimPhase:        Sum: 69us 99% C.I. 5us-9us Avg: 6.272us Max: 9us
ProcessReferences:        Sum: 64us 99% C.I. 3us-18us Avg: 5.818us Max: 18us
InitializePhase:        Sum: 54us 99% C.I. 1us-13us Avg: 4.909us Max: 13us
Sweep:        Sum: 53us 99% C.I. 3us-9us Avg: 4.818us Max: 9us
MarkRoots:        Sum: 41us 99% C.I. 3us-5us Avg: 3.727us Max: 5us
RecursiveMark:        Sum: 32us 99% C.I. 2us-4us Avg: 2.909us Max: 4us
BindBitmaps:        Sum: 25us 99% C.I. 1us-4us Avg: 2.272us Max: 4us
SwapStacks:        Sum: 12us 99% C.I. 1us-2us Avg: 1.090us Max: 2us
SweepLargeObjects:        Sum: 10us 99% C.I. 250ns-1000ns Avg: 909ns Max: 1000ns
(Paused)ProcessMarkStack:        Sum: 2us 99% C.I. 250ns-1000ns Avg: 181ns Max: 1000ns
PreSweepingGcVerification:        Sum: 1us 99% C.I. 250ns-1000ns Avg: 90ns Max: 1000ns
FindDefaultSpaceBitmap:        Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms 
concurrent mark sweep paused:        Sum: 3.508ms 99% C.I. 202us-895us Avg: 318.909us Max: 895us
concurrent mark sweep total time: 196.195ms mean time: 17.835ms
concurrent mark sweep freed: 37401 objects with total size 2029KB
concurrent mark sweep throughput: 190821/s / 10MB/s
Start Dumping histograms for 7 iterations for partial concurrent mark sweep
ProcessMarkStack:        Sum: 261.605ms 99% C.I. 0.007ms-52.128ms Avg: 12.457ms Max: 52.686ms
UpdateAndMarkImageModUnionTable:        Sum: 39.172ms 99% C.I. 2.672ms-9.112ms Avg: 5.596ms Max: 9.112ms
SweepMallocSpace:        Sum: 33.740ms 99% C.I. 0.009ms-23.743ms Avg: 2.410ms Max: 25.130ms
MarkRootsCheckpoint:        Sum: 24.023ms 99% C.I. 0.270ms-6.932ms Avg: 1.715ms Max: 7.087ms
ScanGrayAllocSpaceObjects:        Sum: 17.785ms 99% C.I. 0.014ms-7.313ms Avg: 1.270ms Max: 7.540ms
MarkConcurrentRoots:        Sum: 11.788ms 99% C.I. 4us-2425.500us Avg: 842us Max: 2441us
(Paused)ScanGrayObjects:        Sum: 7.835ms 99% C.I. 0.328ms-2.585ms Avg: 1.119ms Max: 2.585ms
ReMarkRoots:        Sum: 5.637ms 99% C.I. 218us-2109.750us Avg: 805.285us Max: 2131us
SweepLargeObjects:        Sum: 2.383ms 99% C.I. 161us-905us Avg: 340.428us Max: 905us
ScanGrayImageSpaceObjects:        Sum: 2.340ms 99% C.I. 95us-1505us Avg: 334.285us Max: 1505us
UpdateAndMarkZygoteModUnionTable:        Sum: 2.092ms 99% C.I. 248us-340us Avg: 298.857us Max: 340us
ImageModUnionClearCards:        Sum: 2.053ms 99% C.I. 81us-890.500us Avg: 146.642us Max: 931us
AllocSpaceClearCards:        Sum: 1.524ms 99% C.I. 2us-162us Avg: 54.428us Max: 162us
EnqueueFinalizerReferences:        Sum: 1.082ms 99% C.I. 9us-494.750us Avg: 154.571us Max: 495us
MarkNonThreadRoots:        Sum: 798us 99% C.I. 27us-106us Avg: 57us Max: 106us
SweepSystemWeaks:        Sum: 717us 99% C.I. 25us-251us Avg: 102.428us Max: 251us
MarkAllocStackAsLive:        Sum: 640us 99% C.I. 26us-227us Avg: 91.428us Max: 227us
FinishPhase:        Sum: 593us 99% C.I. 58us-126us Avg: 84.714us Max: 126us
ZygoteModUnionClearCards:        Sum: 448us 99% C.I. 28us-42us Avg: 32us Max: 42us
RevokeAllThreadLocalAllocationStacks:        Sum: 269us 99% C.I. 23us-60us Avg: 38.428us Max: 60us
ScanGrayZygoteSpaceObjects:        Sum: 245us 99% C.I. 32us-42us Avg: 35us Max: 42us
MarkRoots:        Sum: 241us 99% C.I. 4us-211us Avg: 34.428us Max: 211us
PreCleanCards:        Sum: 169us 99% C.I. 10us-89us Avg: 24.142us Max: 89us
ProcessReferences:        Sum: 159us 99% C.I. 8us-39us Avg: 22.714us Max: 39us
MarkingPhase:        Sum: 116us 99% C.I. 14us-19us Avg: 16.571us Max: 19us
SwapBitmaps:        Sum: 94us 99% C.I. 11us-15us Avg: 13.428us Max: 15us
(Paused)PausePhase:        Sum: 84us 99% C.I. 8us-14us Avg: 12us Max: 14us
ProcessCards:        Sum: 82us 99% C.I. 4us-8us Avg: 5.857us Max: 8us
ReclaimPhase:        Sum: 55us 99% C.I. 6us-12us Avg: 7.857us Max: 12us
Sweep:        Sum: 53us 99% C.I. 6us-10us Avg: 7.571us Max: 10us
RecursiveMark:        Sum: 40us 99% C.I. 2us-25us Avg: 5.714us Max: 25us
BindBitmaps:        Sum: 16us 99% C.I. 1us-4us Avg: 2.285us Max: 4us
InitializePhase:        Sum: 11us 99% C.I. 1us-3us Avg: 1.571us Max: 3us
UnBindBitmaps:        Sum: 8us 99% C.I. 1us-2us Avg: 1.142us Max: 2us
SweepZygoteSpace:        Sum: 7us 99% C.I. 1us-1us Avg: 1us Max: 1us
(Paused)ProcessMarkStack:        Sum: 6us 99% C.I. 250ns-1000ns Avg: 857ns Max: 1000ns
FindDefaultSpaceBitmap:        Sum: 1us 99% C.I. 250ns-1000ns Avg: 142ns Max: 1000ns
PreSweepingGcVerification:        Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns
Done Dumping histograms 
partial concurrent mark sweep paused:        Sum: 14.159ms 99% C.I. 0.943ms-4.590ms Avg: 2.022ms Max: 4.590ms
partial concurrent mark sweep total time: 417.922ms mean time: 59.703ms
partial concurrent mark sweep freed: 87577 objects with total size 9MB
partial concurrent mark sweep throughput: 210017/s / 23MB/s
Start Dumping histograms for 45 iterations for sticky concurrent mark sweep
ScanGrayAllocSpaceObjects:        Sum: 474.167ms 99% C.I. 0.005ms-31.119ms Avg: 2.634ms Max: 44.113ms
MarkRootsCheckpoint:        Sum: 303.764ms 99% C.I. 0.121ms-65.199ms Avg: 3.375ms Max: 82.807ms
FreeList:        Sum: 155.352ms 99% C.I. 3us-5197.999us Avg: 211.651us Max: 16415us
ScanGrayImageSpaceObjects:        Sum: 103.966ms 99% C.I. 0.089ms-11.839ms Avg: 1.155ms Max: 12.023ms
MarkConcurrentRoots:        Sum: 86.345ms 99% C.I. 3us-7884.999us Avg: 959.388us Max: 9039us
ProcessMarkStack:        Sum: 72.256ms 99% C.I. 1.210us-8796us Avg: 405.932us Max: 11943us
ReMarkRoots:        Sum: 54.893ms 99% C.I. 0.047ms-7.832ms Avg: 1.219ms Max: 7.888ms
SweepArray:        Sum: 50.684ms 99% C.I. 0.072ms-5.475ms Avg: 1.126ms Max: 5.690ms
(Paused)ScanGrayObjects:        Sum: 44.636ms 99% C.I. 0.257ms-6.706ms Avg: 1.038ms Max: 6.837ms
AllocSpaceClearCards:        Sum: 20.095ms 99% C.I. 2us-1074.999us Avg: 111.638us Max: 3549us
MarkingPhase:        Sum: 10.223ms 99% C.I. 188us-370us Avg: 227.177us Max: 370us
ImageModUnionClearCards:        Sum: 8.928ms 99% C.I. 77us-354.999us Avg: 99.200us Max: 376us
SweepSystemWeaks:        Sum: 8.232ms 99% C.I. 18us-2006.250us Avg: 182.933us Max: 2356us
MarkNonThreadRoots:        Sum: 5.437ms 99% C.I. 17us-254.999us Avg: 60.411us Max: 296us
RevokeAllThreadLocalAllocationStacks:        Sum: 5.147ms 99% C.I. 7us-2176.250us Avg: 114.377us Max: 2715us
ScanGrayZygoteSpaceObjects:        Sum: 3.604ms 99% C.I. 32us-140us Avg: 41.906us Max: 140us
ZygoteModUnionClearCards:        Sum: 3.034ms 99% C.I. 27us-157us Avg: 35.279us Max: 169us
EnqueueFinalizerReferences:        Sum: 2.413ms 99% C.I. 3us-372us Avg: 53.622us Max: 372us
(Paused)ScanGrayImageSpaceObjects:        Sum: 1.899ms 99% C.I. 182us-1717us Avg: 949.500us Max: 1717us
FinishPhase:        Sum: 1.806ms 99% C.I. 22us-66us Avg: 40.133us Max: 66us
ResetStack:        Sum: 1.720ms 99% C.I. 16us-138.750us Avg: 38.222us Max: 141us
ProcessCards:        Sum: 1.162ms 99% C.I. 4us-324.999us Avg: 12.911us Max: 535us
PreCleanCards:        Sum: 827us 99% C.I. 8us-205us Avg: 18.377us Max: 227us
(Paused)PausePhase:        Sum: 568us 99% C.I. 7us-28us Avg: 12.622us Max: 28us
ReclaimPhase:        Sum: 366us 99% C.I. 6us-34us Avg: 8.133us Max: 34us
ProcessReferences:        Sum: 318us 99% C.I. 3us-28us Avg: 7.066us Max: 28us
SwapBitmaps:        Sum: 283us 99% C.I. 5us-12us Avg: 6.288us Max: 12us
MarkRoots:        Sum: 208us 99% C.I. 3us-14us Avg: 4.622us Max: 14us
BindBitmaps:        Sum: 195us 99% C.I. 1us-88.750us Avg: 4.333us Max: 94us
RecordFree:        Sum: 111us 99% C.I. 1us-57us Avg: 2.466us Max: 57us
UnBindBitmaps:        Sum: 110us 99% C.I. 1us-17us Avg: 2.444us Max: 17us
InitializePhase:        Sum: 96us 99% C.I. 1us-10us Avg: 2.133us Max: 10us
(Paused)ScanGrayAllocSpaceObjects:        Sum: 82us 99% C.I. 1us-44us Avg: 20.500us Max: 44us
SwapStacks:        Sum: 73us 99% C.I. 1us-3us Avg: 1.622us Max: 3us
(Paused)ProcessMarkStack:        Sum: 58us 99% C.I. 0.250us-12us Avg: 1.288us Max: 12us
ForwardSoftReferences:        Sum: 51us 99% C.I. 1us-3us Avg: 1.186us Max: 3us
FindDefaultSpaceBitmap:        Sum: 49us 99% C.I. 0.250us-3us Avg: 1.088us Max: 3us
PreSweepingGcVerification:        Sum: 4us 99% C.I. 250ns-1000ns Avg: 88ns Max: 1000ns
Done Dumping histograms 
sticky concurrent mark sweep paused:        Sum: 124.287ms 99% C.I. 0.304ms-11.662ms Avg: 2.761ms Max: 11.880ms
sticky concurrent mark sweep total time: 1.423s mean time: 31.625ms
sticky concurrent mark sweep freed: 700436 objects with total size 38MB
sticky concurrent mark sweep throughput: 492225/s / 26MB/s
Total time spent in GC: 2.037s
Mean GC size throughput: 22MB/s
Mean GC object throughput: 428302 objects/s
Total number of allocations 1117995
Total bytes allocated 69MB
Free memory 288KB
Free memory until GC 288KB
Free memory until OOME 232MB
Total memory 23MB
Max memory 256MB
Total mutator paused time: 141.954ms
Total time waiting for GC to complete: 10.373msDALVIK THREADS (62):
"main" prio=5 tid=1 Native| group="main" sCount=1 dsCount=0 obj=0x735bce70 self=0xf4827400| sysTid=2344 nice=0 cgrp=default sched=0/0 handle=0xf755dbec| state=S schedstat=( 5284226033 2189387546 17012 ) utm=444 stm=84 core=3 HZ=100| stack=0xff483000-0xff485000 stackSize=8MB| held mutexes=kernel: __switch_to+0x8c/0x98kernel: SyS_epoll_wait+0x304/0x44ckernel: compat_SyS_epoll_pwait+0x11c/0x128kernel: cpu_switch_to+0x48/0x4cnative: #00 pc 0003b1e0  /system/lib/libc.so (__epoll_pwait+20)native: #01 pc 00015213  /system/lib/libc.so (epoll_pwait+26)native: #02 pc 00015221  /system/lib/libc.so (epoll_wait+6)native: #03 pc 000127fb  /system/lib/libutils.so (android::Looper::pollInner(int)+98)native: #04 pc 00012a29  /system/lib/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+92)native: #05 pc 000858ed  /system/lib/libandroid_runtime.so (android::NativeMessageQueue::pollOnce(_JNIEnv*, int)+22)native: #06 pc 000b4f6b  /data/dalvik-cache/arm/system@framework@boot.oat (Java_android_os_MessageQueue_nativePollOnce__JI+102)at android.os.MessageQueue.nativePollOnce(Native method)at android.os.MessageQueue.next(MessageQueue.java:148)at android.os.Looper.loop(Looper.java:151)at android.app.ActivityThread.main(ActivityThread.java:5650)at java.lang.reflect.Method.invoke!(Native method)at java.lang.reflect.Method.invoke(Method.java:372)at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:960)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:755)"AsyncTask #1" prio=5 tid=39 Waiting| group="main" sCount=1 dsCount=0 obj=0x1351c280 self=0xf4bc4000| sysTid=2797 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0xe0bf1000| state=S schedstat=( 990359192 4076806009 17356 ) utm=65 stm=34 core=1 HZ=100| stack=0xdeef4000-0xdeef6000 stackSize=1036KB| held mutexes=at java.lang.Object.wait!(Native method)- waiting on <0x08a7c4b6> (a java.lang.Object)at java.lang.Thread.parkFor(Thread.java:1220)- locked <0x08a7c4b6> (a java.lang.Object)at sun.misc.Unsafe.park(Unsafe.java:299)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:410)at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1035)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1097)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)at java.lang.Thread.run(Thread.java:818)

Heap部分

Heap: 3% free, 22MB/23MB; 243971 objects

在JVM中，堆（Heap）是用于存储所有对象实例的主要内存区域。‘Heap: 3% free, 22MB/23MB; 243971 objects’ 这行信息通常是由Java的垃圾收集器（Garbage Collector）输出的，用于描述堆内存的使用情况。

‘3% free’ 表示堆内存中只有3%的空间是空闲的。
‘22MB/23MB’ 表示当前堆内存已使用22MB，总大小为23MB。
‘243971 objects’ 表示当前堆内存中有243971个对象实例。
当堆内存中的空闲空间不足时，JVM会尝试进行垃圾收集，以回收不再使用的对象占用的内存。如果垃圾收集后仍然没有足够的空间，那么JVM会尝试扩大堆的大小，或者报告内存溢出错误（OutOfMemoryError），这取决于JVM的配置和垃圾收集器的策略。

垃圾回收器输出的histograms 部分

Done Dumping histograms 
sticky concurrent mark sweep paused:        Sum: 5.399ms 99% C.I. 1.436ms-2.103ms Avg: 1.799ms Max: 2.103ms
sticky concurrent mark sweep total time: 89.691ms mean time: 29.897ms
sticky concurrent mark sweep freed: 198493 objects with total size 7MB
sticky concurrent mark sweep throughput: 2.23026e+06/s / 80MB/s
Total time spent in GC: 181.554ms
Mean GC size throughput: 303MB/s
Mean GC object throughput: 6.09857e+06 objects/s
Total number of allocations 1351190
Total bytes allocated 77MB
Free memory 748KB
Free memory until GC 748KB
Free memory until OOME 233MB
Total memory 23MB
Max memory 256MB
Total mutator paused time: 7.310ms
Total time waiting for GC to complete: 10.382ms

这段日志来自于Android的垃圾收集器（Garbage Collector），具体地，是Concurrent Mark Sweep（CMS）垃圾收集器的日志。CMS是一种使用标记-清除算法的垃圾收集器，它在Java和Android中被广泛使用。
解释如下：

‘Done Dumping histograms’：直方图的数据已经导出完成。
‘sticky concurrent mark sweep paused’：CMS标记阶段暂停的时间，包括总时间、99%的置信区间、平均值、最大值。
‘sticky concurrent mark sweep total time’：CMS标记阶段总时间，包括平均时间。
‘sticky concurrent mark sweep freed’：CMS标记阶段释放的对象数量和总大小。
‘sticky concurrent mark sweep throughput’：CMS标记阶段的吞吐量，包括对象吞吐量和字节吞吐量。
‘Total time spent in GC’：在垃圾收集上花费的总时间。
‘Mean GC size throughput’：平均每次GC的字节吞吐量。
‘Mean GC object throughput’：平均每次GC的对象吞吐量。
‘Total number of allocations’：分配的总对象数量。
‘Total bytes allocated’：分配的总字节数。
‘Free memory’：当前空闲内存。
‘Free memory until GC’：GC前的空闲内存。
‘Free memory until OOME’：OutOfMemoryError前的空闲内存。
‘Total memory’：总内存。
‘Max memory’：最大内存。
‘Total mutator paused time’：应用程序暂停的总时间。
‘Total time waiting for GC to complete’：等待GC完成的总时间。

Thread部分

"main" prio=5 tid=1 Native
"FinalizerDaemon" daemon prio=5 tid=7 Waiting
"ARouter task pool No.1, thread No.1" prio=5 tid=16 Waiting
"ARouter task pool No.1, thread No.2" prio=5 tid=17 Waiting

线程状态有5种：新建、就绪、执行、阻塞、死亡。而Java中的线程状态有6种，6种状态都定义在：java.lang.Thread.State中在这里插入图片描述
main线程的native是什么状态，哪来的？其实trace文件中的状态是是CPP代码中定义的状态，下面是一张对应关系表。
main函数的native状态是正在执行JNI函数。堆栈信息是我们分析ANR的第一个重要的信息，一般来说：