系列文章目录
提示:这里可以添加系列文章的所有文章的目录,目录需要自己手动添加
例如:第一章 Python 机器学习入门之pandas的使用
文章目录
- 系列文章目录
- 前言
- 一、trace.txt文件示例
- 二、日志分析
- 2.1 CPU 负载
- 2.2 内存信息
- 2.3 堆栈信息
- schedstat含义说明:
- 2.4 线程状态
- 三、trace文件中常见线程状态
- 3.1 Blocked状态
- 3.2 Waiting状态
- 3.3 Runnable状态
- 3.4 Running状态
- 3.5 Native状态
- 3.6 Suspended状态
- 总结
前言
一、trace.txt文件示例
Build Info: 'alps-mp-r0.mp1:alps-mp-r0.mp1-V8.24.1_reallytek.r0mp1.k61v1.64.bsp_P138:mt6761:S01,TECNO/KF6h-GL/TECNO-KF6h:11/RP1A.200720.011/220711V496DevT:user/release-keys'
MSSI Info: 'TECNO/TSSI/AGo-32:11/RP1A.200720.011/220711V349:user/release-keys'
Exception Log Time:[Tue Feb 14 12:54:09 CST 2023] [22627.297038]
Exception Class: ANR
Exception Type: data_app_anr
Current Executing Process:
com.xxx.xxx
com.xxx.xxx v6433 (6.4.33)
Trigger time:[2023-02-14 12:54:09.261127] pid:406
Backtrace:
Process: com.xxx.xxx
PID: 406
UID: 10632
Flags: 0x30d83e44
Package: com.xxx.xxx v6433 (6.4.33)
Foreground: Yes
Process-Runtime: 8164728
Activity: com.xxx.xxx/com.xxx.ui.mall.activity.XxxWebActivity
Subject: Input dispatching timed out (ActivityRecord{5e21df u0 com.xxx.xxx.lite/com.xxx.ui.mall.activity
.XxxWebActivity t97310} does not have a focused window)
Build: TECNO/KF6h-GL/TECNO-KF6h:11/RP1A.200720.011/220711V496DevT:user/release-keys
ANR in com.xxx.xxx, time=29737782
Reason: executing service com.xxx.xxx/.service.XxxService //ANR原因
Load: 16.06 / 14.89 / 12.93
Android time :[2023-04-12 19:45:04.30] [29741.248]
CPU usage from 94138ms to 0ms ago (2023-04-12 19:43:26.700 to 2023-04-12 19:45:00.838):
32% 30133/com.google.android.gms: 26% user + 5.8% kernel / faults: 156889 minor
30% 1002/system_server: 20% user + 10% kernel / faults: 33892 minor
13% 347/surfaceflinger: 6.6% user + 6.6% kernel / faults: 3476 minor
9.9% 1398/com.android.systemui: 8.1% user + 1.8% kernel / faults: 35960 minor 1 major
7.7% 15823/adbd: 1.9% user + 5.7% kernel / faults: 36366 minor
4.2% 222/mmcqd/0: 0% user + 4.2% kernel
3.4% 17495/com.android.defcontainer: 1.6% user + 1.7% kernel / faults: 1783 minor
3.4% 1565/tx_thread: 0% user + 3.4% kernel
3.3% 17461/com.android.settings: 2.4% user + 0.9% kernel / faults: 11452 minor
3.3% 220/exe_cq: 0% user + 3.3% kernel
3.2% 300/logd: 0.9% user + 2.3% kernel / faults: 76 minor
2.6% 346/servicemanager: 1% user + 1.5% kernel
2.5% 7889/com.google.android.gms.persistent: 2% user + 0.5% kernel / faults: 2454 minor
2.5% 216/hps_main: 0% user + 2.5% kernel
2.3% 481/installd: 0.1% user + 2.2% kernel
2.1% 451/aal: 0.7% user + 1.4% kernel
1.7% 454/media.codec: 1.1% user + 0.6% kernel / faults: 20602 minor
1.2% 15843/logcat: 0.5% user + 0.6% kernel
1.2% 1628/com.android.phone: 0.8% user + 0.3% kernel / faults: 410 minor
1.2% 15845/logcat: 0.5% user + 0.6% kernel
1% 3341/com.transsion.phoenix:service: 0.6% user + 0.3% kernel / faults: 2 minor
0.9% 590/akmd09911: 0.2% user + 0.7% kernel / faults: 6 minor
0.9% 2093/com.transsion.hilauncher: 0.7% user + 0.2% kernel / faults: 9318 minor
0.9% 417/disp_queue_P0: 0% user + 0.9% kernel
0.8% 17272/com.transsion.phoenix: 0.5% user + 0.2% kernel
0.6% 15154/kworker/u17:3: 0% user + 0.6% kernel
0.6% 12696/kworker/u17:2: 0% user + 0.6% kernel
0.6% 7/rcu_preempt: 0% user + 0.6% kernel
0.6% 8/rcu_sched: 0% user + 0.6% kernel
0.2% 11758/kworker/0:3: 0% user + 0.2% kernel
0.5% 74/ion_mm_heap: 0% user + 0.5% kernel
0.5% 3508/com.transsion.phonemaster: 0.3% user + 0.1% kernel / faults: 78 minor
0.5% 15503/kworker/u17:1: 0% user + 0.5% kernel
0.4% 13509/kworker/u16:0: 0% user + 0.4% kernel
0.4% 16252/kworker/u17:4: 0% user + 0.4% kernel
0.4% 806/com.android.vending: 0.4% user + 0% kernel / faults: 2258 minor
0.4% 15319/kworker/u16:2: 0% user + 0.4% kernel
0.4% 13884/kworker/u16:1: 0% user + 0.4% kernel
0.4% 14459/kworker/0:4: 0% user + 0.4% kernel
0.4% 16329/kworker/u16:5: 0% user + 0.4% kernel
0.3% 11433/kworker/0:5: 0% user + 0.3% kernel
0.3% 201/disp_delay_trig: 0% user + 0.3% kernel
0.3% 10/migration/0: 0% user + 0.3% kernel
0.3% 434/jbd2/dm-1-8: 0% user + 0.3% kernel
0.3% 69/dvfs_nfy: 0% user + 0.3% kernel
0.2% 11/migration/1: 0% user + 0.2% kernel
0.2% 398/dmcrypt_write: 0% user + 0.2% kernel
0.2% 17482/com.google.android.packageinstaller: 0.2% user + 0% kernel / faults: 928 minor
0.2% 486/netd: 0% user + 0.1% kernel / faults: 1273 minor
0.2% 17777/com.tencent.mobileqq:MSF: 0.1% user + 0% kernel / faults: 81 minor
0.2% 203/present_fence_w: 0% user + 0.2% kernel
0.2% 2232/kworker/1:2: 0% user + 0.2% kernel
0.2% 15/migration/2: 0% user + 0.2% kernel
0.2% 133/pbm: 0% user + 0.2% kernel
0% 15352/kworker/0:2: 0% user + 0% kernel
0.2% 73/cfinteractive: 0% user + 0.2% kernel
0.1% 23/migration/4: 0% user + 0.1% kernel
0.1% 14222/kworker/1:3: 0% user + 0.1% kernel
0.1% 14811/kworker/u16:3: 0% user + 0.1% kernel
0.1% 19/migration/3: 0% user + 0.1% kernel
0.1% 478/audioserver: 0% user + 0% kernel / faults: 162 minor
0.1% 15776/kworker/7:2: 0% user + 0.1% kernel
0.1% 27/migration/5: 0% user + 0.1% kernel
0.1% 348/mtkmal: 0.1% user + 0% kernel
0.1% 482/keystore: 0.1% user + 0% kernel
0.1% 31/migration/6: 0% user + 0.1% kernel
0.1% 247/charger_thread: 0% user + 0.1% kernel
0.1% 345/lmkd: 0% user + 0% kernel
0.1% 15775/kworker/5:0: 0% user
70% TOTAL: 38% user + 31% kernel + 0.2% iowait + 0.1% softirq
----- 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: 19952
Metrics:
ClassLoadingTotalTime: count = 17358
ClassVerificationTotalTime: count = 15303
ClassVerificationCount: count = 28
WorldStopTimeDuringGCAvg: count = 0
YoungGcCount: count = 0
FullGcCount: count = 0
TotalBytesAllocated: count = 2349168
TotalGcCollectionTime: count = 0
YoungGcThroughputAvg: count = 0
FullGcThroughputAvg: count = 0
YoungGcTracingThroughputAvg: count = 0
FullGcTracingThroughputAvg: count = 0
JitMethodCompileTotalTime: count = 28492
JitMethodCompileCount: count = 39
YoungGcCollectionTime: range = 0...60000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
FullGcCollectionTime: range = 0...60000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
YoungGcThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
FullGcThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
YoungGcTracingThroughput: range = 0...10000, buckets: 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0
FullGcTracingThroughput: 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 23
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 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 1
at 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)
...
/** =====================线程信息-结束============================================================================*/
二、日志分析
发生ANR的时候,系统会产生一份anr日志文件(手机的/data/anr 目录下,文件名称可能各厂商不一样,业内大多称呼为trace文件),内含如下几项重要信息。
2.1 CPU 负载
Reason: executing service com.xxx.xxx/.service.XxxService
Load: 16.06 / 14.89 / 12.93
CPU usage from 0ms to 1130ms ago (2023-04-12 19:43:26.700 to 2023-04-12 19:44:56.838):
32% 30133/com.google.android.gms: 26% user + 5.8% kernel / faults: 156889 minor
30% 1002/system_server: 20% user + 10% kernel / faults: 33892 minor
........省略N行.....
70% TOTAL: 38% user + 31% kernel + 0.2% iowait + 0.7% irq + 0.1% softirq
如上所示:
- 第一行:发生ANR的原因
- 第二行:1、5、15 分钟内正在使用和等待使用CPU 的活动进程的平均数
- 第三行:表明负载信息抓取在ANR发生之后的0~1130ms。同时也指明了ANR的时间点:2023-04-12 19:44:56.838
- 中间部分:各个进程占用的CPU的详细情况
- 最后一行:各个进程合计占用的CPU信息。
名词解释:
- user:用户态,kernel:内核态
- faults:内存缺页,minor——轻微的,major——重度,需要从磁盘拿数据
- iowait:IO使用(等待)占比
- irq:硬中断,softirq:软中断
注意:
-
iowait占比很高,意味着有很大可能,是io耗时导致ANR,具体进一步查看有没有进程faults major比较多。
-
单进程CPU的负载并不是以100%为上限,而是有几个核,就有百分之几百,如4核上限为400%。
2.2 内存信息
Total number of allocations 214578 进程创建到现在一共创建了多少对象
Total bytes allocated 32MB 进程创建到现在一共申请了多少内存
Total bytes freed 10MB 进程创建到现在一共释放了多少内存
Free memory 335KB 不扩展堆的情况下可用的内存
Free memory until GC 335KB GC前的可用内存
Free memory until OOME 361MB OOM之前的可用内存
Total memory 22MB 当前总内存(已用+可用)
Max memory 384MB 进程最多能申请的内存
从含义可以得出结论:**Free memory until OOME **的值很小的时候,已经处于内存紧张状态。应用可能是占用了过多内存。
ps:如果ANR时间点前后,日志里有打印onTrimMemory,也可以作为内存紧张的一个参考判断
2.3 堆栈信息
"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=
参数解读说明:
- 第0行:
- 线程名: Binder:1002_1(如有daemon则代表守护线程)
- prio: 线程优先级
- tid: 线程内部id
- 线程状态: NATIVE
- 第1行:
- group: 线程所属的线程组
- sCount: 线程挂起次数
- dsCount: 用于调试的线程挂起次数
- obj: 当前线程关联的java线程对象
- self: 当前线程地址
- 第2行:
- sysTid:线程真正意义上的tid
- nice: 调度优先级,nice值越小则优先级越高。
- cgrp: 进程所属的进程调度组
- sched: 调度策略
- handle: 函数处理地址
- 第3行:
- state: 线程状态
- schedstat: CPU调度时间统计, 见proc/[pid]/task/[tid]/schedstat
- utm/stm: 用户态/内核态的CPU时间(单位是jiffies), 见proc/[pid]/task/[tid]/stat
- core: 该线程的最后运行所在核
- HZ: 时钟频率
- 第4行:
- stack:线程栈的地址区间
- stackSize:栈的大小
- 第5行:
- mutex: 所持有mutex类型,有独占锁exclusive和共享锁shared两类
schedstat含义说明:
nice值越小则优先级越高。此处nice=-0,可见优先级相对较高;
schedstat括号中的3个数字依次是Running、Runable、Switch,紧接着的是utm和stm
- Running时间:CPU运行的时间,单位ns
- Runable时间:RQ队列的等待时间,单位ns
- Switch次数:CPU调度切换次数
- utm: 该线程在用户态所执行的时间,单位是jiffies,jiffies定义为sysconf(_SC_CLK_TCK),默认等于10ms
- stm: 该线程在内核态所执行的时间,单位是jiffies,默认等于10ms
可见,该线程Running = 19616954905 ns,也约等于19616ms。在CPU运行时间包括用户态(utm)和内核态(stm)。 utm + stm = (1314 + 647) ×10 ms = 19610ms。
结论:utm + stm = schedstat第一个参数值。
2.4 线程状态
堆栈信息中ANR发生的进程当前线程的状态,也是分析ANR问题的一个重要信息。
"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 23
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 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.TransBaseActivity.toggleTranslucent(TransBaseActivity.java:37)
at com.xxx.common.base.TransBaseActivity.onCreate(TransBaseActivity.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)
........省略N行.....
"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,它的状态是Blocked。另一个是Binder:1002_1,它的状态是Native。
教科书上说线程状态有5种:新建、就绪、执行、阻塞、死亡。而Java中的线程状态有6种,6种状态都定义在:java.lang.Thread.State中:
对应解释如下:
如上trace文件中的状态不止包含上述状态,还包含native等状态,多出来的状态哪来的?
其实trace文件中的状态还包含了CPP代码中定义的状态,下面是一张对应关系表:
下面我们继续看这些常见状态的案例。
三、trace文件中常见线程状态
Tips:Java中状态:
3.1 Blocked状态
"main" tid=1 systid=17151 blocked | waiting to lock <0x05dfb3bd> (java.lang.Object) held by thread 46
at 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)
…省略N行…
RxCachedThreadScheduler-4 tid=46 systid=17212 native
at libcore.io.Linux.access(Linux.java)
at libcore.io.ForwardingOs.access(ForwardingOs.java:72)
at libcore.io.BlockGuardOs.access(BlockGuardOs.java:73)
at libcore.io.ForwardingOs.access(ForwardingOs.java:72)
at android.app.ActivityThread$AndroidOs.access(ActivityThread.java:7982)
at java.io.UnixFileSystem.checkAccess(UnixFileSystem.java:281)
at java.io.File.exists(File.java:815)
at android.app.ContextImpl.ensureExternalDirsExistOrFilter(ContextImpl.java:3022)
at android.app.ContextImpl.getExternalFilesDirs(ContextImpl.java:779)
at android.app.ContextImpl.getExternalFilesDir(ContextImpl.java:768)
at android.content.ContextWrapper.getExternalFilesDir(ContextWrapper.java:276)
at com.xxx.storage.cache.ScopeStorageUtils.getBPRootDir(ScopeStorageUtils.java:121)
at com.xxx.storage.cache.ScopeStorageUtils.getBPRootPath(ScopeStorageUtils.java:134)
at com.xxx.storage.cache.ScopeStorageUtils.shouldUseScopeStorage(ScopeStorageUtils.java:49)
at com.xxx.util.PhoneDeviceUtil.getXxLocalDir(PhoneDeviceUtil.java:881)
at com.xxx.util.PhoneDeviceUtil.getCacheDirPath(PhoneDeviceUtil.java:914)
at com.xxx.xx.download.db.FileDownloaderDBHelper.<init>(FileDownloaderDBHelper.java:43)
at com.xxx.xx.download.db.FileDownloaderDB.initDBAndCheckUpdate(FileDownloaderDB.java:49)
at com.xxx.xx.download.db.FileDownloaderDB.<init>(FileDownloaderDB.java:44)
at com.xxx.xx.download.db.FileDownloaderDB.<init>(FileDownloaderDB.java:38)
at com.xxx.xx.download.db.FileDownloaderDB$Holder.<clinit>(FileDownloaderDB.java:60)
at com.xxx.xx.download.db.FileDownloaderDB.getInstance(FileDownloaderDB.java:65)
at com.xxx.storage.cache.PlaylistDB.getDB(PlaylistDB.java:57)
at com.xxx.storage.cache.PlaylistDB.query(PlaylistDB.java:349)
at com.xxx.storage.cache.HistoryPlaylistCache.queryDB(HistoryPlaylistCache.java:192)
at com.xxx.storage.cache.HistoryPlaylistCache.<init>(HistoryPlaylistCache.java:39)
at com.xxx.storage.cache.ItemCache.init(ItemCache.java:151)
at com.xxx.common.base.XxApplicationInitor.init1(XxApplicationInitor.java:285)
at com.xxx.common.base.XxApplicationInitor.access$500(XxApplicationInitor.java:115)
at com.xxx.common.base.XxApplicationInitor$4.subscribe(XxApplicationInitor.java:177)
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:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
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:923)
由示例可知当前主线程被thread 46所阻塞。
3.2 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)
…省略N行…
"RxCachedThreadScheduler-2" daemon prio=5 tid=35 Waiting
| group="main" sCount=1 dsCount=0 flags=1 obj=0x12d428b0 self=0x92201400
| sysTid=8619 nice=0 cgrp=default sched=0/0 handle=0x7cd13230
| state=S schedstat=( 392687759 254464345 648 ) utm=33 stm=6 core=0 HZ=100
| stack=0x7cc10000-0x7cc12000 stackSize=1040KB
| held mutexes=
at b.a.b.c.a.l.j(:4)
- waiting on <0x01a76acd> (a java.lang.Class<b.a.b.c.a.k>)
at b.a.b.c.a.l.<clinit>(:1)
at b.a.b.c.a.l.b(:1)
at com.xxx.common.base.r.t(:6)
at com.xxx.common.base.r.k(:22)
at com.xxx.common.base.r.d(:1)
at com.xxx.common.base.k.a(:1)
at io.reactivex.internal.operators.observable.w0.subscribeActual(:3)
at io.reactivex.m.subscribe(:14)
at io.reactivex.internal.operators.observable.g6$a.run(:1)
at io.reactivex.u.run(:2)
at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:2)
at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:1)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:301)
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:919)
- waiting on <0x077aff1b> (a java.lang.Class<b.a.b.c.a.l>)
根据示例可知当前主线程在等待获取<0x077aff1b>,继而搜索<0x077aff1b>发现当前trace.txt中无结果;退而求其次,继续搜索b.a.b.c.a.l,发现thread-35中在同时访问b.a.b.c.a.l中线程安全的方法b.a.b.c.a.l.j
Tips:Java & C 共有状态:
3.3 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)
示例为C中Runnable状态,表示当前线程可运行或正在运行。
上述示例中main-主线程状态为Runnable,为什么还会发生ANR呢?
这是因为虽然当前主线程状态为Runnable,但是可能有其它频繁调度的任务,导致cpu资源不足,无法及时执行到当前主线程,这个等待时间超过了ANR等待阈值,则会触发ANR,故需排查当前是否有频繁执行的任务。
Tips:C中状态:
3.4 Running状态
3.5 Native状态
"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)
Native状态–表示当前线程正在执行native层,C中代码。
Native状态仅凭当前主线程堆栈,无法判定引起ANR的原因就是当前捕获堆栈,需要结合mainlog排查发生ANR时间点前后执行的任务信息,进一步分析确定。
3.6 Suspended状态
总结
致谢:
解读Java进程的Trace文件
vivo分享干货:ANR日志分析全面解析
ANR显示和日志生成原理讲解