什么是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的第一個重要的信息,一般來說:
- main線程處于 BLOCK、WAITING、TIMEWAITING狀態,那基本上是函數阻塞導致ANR;
- 如果main線程無異常,則應該排查CPU負載和內存環境。