android 拉取traces.txt分析ANR

什么是ANR

ANR即Application Not Responding的缩写，就是应用无响应

首先ANR的发生是有条件限制的，分为以下三点：

1.只有主线程才会产生ANR，主线程就是UI线程；

2.必须发生某些输入事件或特定操作，比如按键或触屏等输入事件，在BroadcastReceiver或Service的各个生命周期调用函数；

3.上述事件响应超时，不同的context规定的上限时间不同

a.主线程对输入事件5秒内没有处理完毕，即阻塞
b.主线程在执行BroadcastReceiver的onReceive()函数时10秒内没有处理完毕
c.主线程在Service的各个生命周期函数时20秒内没有处理完毕

发生ANR后拉取traces.txt分析问题

当系统中有app出现ANR时，当系统中有应用出现ANR时，framework会在弹出Dialog的同时dump出当前各线程的堆栈情况，生成traces.txt文件，方便开发者分析出ANR的root cause。traces文件位于安卓系统下/data/anr目录中；

在这里我们从一份简单的ANR示例来研究当发生ANR后，如何拉取traces.txt文件并分析出ANR原因;

以下为代码示例，很明显的错误，这里假如我们并不知情

下面开始一步一步描述分析问题的步骤

1.导出traces.txt文件
traces.txt位于/data/anr中，无需root权限即可通过pull命令获取，下面的命令可以将traces.txt文件拷贝到当前目录下

因手机厂商可能会自行修改trace文件的命名方式和管理方式，traces文件名和所在目录可能会存在差异，但肯定会再/data/anr/目录下，所以我们可以通过adb shell 进入到 “/data/anr/” 目录下查看traces文件，上图为我再小米手机上导出traces文件的截图，可以看出小米手机是根据anr发生的时间来命名的。

adb shell 进入shell命令模式
cd /data/anr/ 进入anr目录下
ls -a 查看当前目录下的所有文件
adb pull data/anr/anr_2020-09-05-16-03-04-828 导出trace文件到adb命令目录下。

如果拉取遇到权限问题，可以使用“adb bugreport”命令。会在adb命令所处的目录下生成一个 zip 文件。解压缩后，在“FS/data/anr” 目录下能看到 anr 文件，不过可能没有后缀，直接用文本软件打开即可。

2.分析traces.txt文件

先看一下traces文件内容，内容较多，无需恐慌，我们只找我们想要的即可

//说明了发生ANR的进程id、时间和进程名称。
----- pid 3551 at 2020-09-05 16:03:04 -----
//发生anr的app包名
Cmd line: com.tiano.anrdemo
Build fingerprint: 'Xiaomi/crux/crux:10/QKQ1.190825.002/V12.0.3.0.QFXCNXM:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=8200 post zygote classes=337
Dumping registered class loaders
#0 dalvik.system.PathClassLoader: [], parent #1
#1 java.lang.BootClassLoader: [], no parent
#2 dalvik.system.PathClassLoader: [/system/framework/tcmclient.jar], parent #0
#3 dalvik.system.PathClassLoader: [], parent #0
#4 dalvik.system.PathClassLoader: [/data/app/com.tiano.anrdemo-VyqkZUePQCFk45qOWaBtzw==/base.apk:/data/app/com.tiano.anrdemo-VyqkZUePQCFk45qOWaBtzw==/base.apk!classes2.dex], parent #1
#5 dalvik.system.PathClassLoader: [/system/app/MiuiContentCatcher/MiuiContentCatcher.apk], parent #1
#6 dalvik.system.PathClassLoader: [/system/app/CatcherPatch/CatcherPatch.apk], parent #1
Done dumping class loaders
Intern table: 87931 strong; 376 weak
JNI: CheckJNI is on; globals=727 (plus 43 weak)
Libraries: libandroid.so libcompiler_rt.so libjavacore.so libjavacrypto.so libjnigraphics.so libmedia_jni.so libmiuinative.so libopenjdk.so libqti_performance.so libsoundpool.so libwebviewchromium_loader.so (11)
Heap: 93% free, 1754KB/25MB; 50911 objects
Dumping cumulative Gc timings
Average major GC reclaim bytes ratio inf over 0 GC cycles
Average major GC copied live bytes ratio 0.0105241 over 681 major GCs
Cumulative bytes moved 12867064
Cumulative objects moved 168559
Peak regions allocated 253 (63MB) / 1024 (256MB)
Start Dumping histograms for 1 iterations for young concurrent copying
ScanImmuneSpaces:   Sum: 9.844ms 99% C.I. 9.844ms-9.844ms Avg: 9.844ms Max: 9.844ms
ProcessMarkStack:   Sum: 9.498ms 99% C.I. 9.498ms-9.498ms Avg: 9.498ms Max: 9.498ms
VisitConcurrentRoots:   Sum: 5.391ms 99% C.I. 5.391ms-5.391ms Avg: 5.391ms Max: 5.391ms
ClearFromSpace: Sum: 1.043ms 99% C.I. 1.043ms-1.043ms Avg: 1.043ms Max: 1.043ms
GrayAllDirtyImmuneObjects:  Sum: 889us 99% C.I. 889us-889us Avg: 889us Max: 889us
InitializePhase:    Sum: 709us 99% C.I. 709us-709us Avg: 709us Max: 709us
ScanCardsForSpace:  Sum: 484us 99% C.I. 484us-484us Avg: 484us Max: 484us
FlipOtherThreads:   Sum: 413us 99% C.I. 413us-413us Avg: 413us Max: 413us
SweepSystemWeaks:   Sum: 369us 99% C.I. 369us-369us Avg: 369us Max: 369us
VisitNonThreadRoots:    Sum: 196us 99% C.I. 196us-196us Avg: 196us Max: 196us
EnqueueFinalizerReferences: Sum: 171us 99% C.I. 171us-171us Avg: 171us Max: 171us
RecordFree: Sum: 76us 99% C.I. 0.500us-76us Avg: 38us Max: 76us
ProcessReferences:  Sum: 62us 99% C.I. 5us-57us Avg: 31us Max: 57us
(Paused)ClearCards: Sum: 58us 99% C.I. 0.263us-54us Avg: 2.900us Max: 54us
(Paused)GrayAllNewlyDirtyImmuneObjects: Sum: 54us 99% C.I. 54us-54us Avg: 54us Max: 54us
ThreadListFlip: Sum: 51us 99% C.I. 51us-51us Avg: 51us Max: 51us
ForwardSoftReferences:  Sum: 34us 99% C.I. 34us-34us Avg: 34us Max: 34us
MarkZygoteLargeObjects: Sum: 22us 99% C.I. 22us-22us Avg: 22us Max: 22us
FreeList:   Sum: 17us 99% C.I. 17us-17us Avg: 17us Max: 17us
ResumeRunnableThreads:  Sum: 12us 99% C.I. 12us-12us Avg: 12us Max: 12us
(Paused)SetFromSpace:   Sum: 10us 99% C.I. 10us-10us Avg: 10us Max: 10us
EmptyRBMarkBitStack:    Sum: 9us 99% C.I. 9us-9us Avg: 9us Max: 9us
(Paused)FlipCallback:   Sum: 8us 99% C.I. 8us-8us Avg: 8us Max: 8us
FlipThreadRoots:    Sum: 7us 99% C.I. 7us-7us Avg: 7us Max: 7us
SwapBitmaps:    Sum: 6us 99% C.I. 6us-6us Avg: 6us Max: 6us
UnBindBitmaps:  Sum: 3us 99% C.I. 3us-3us Avg: 3us Max: 3us
ResumeOtherThreads: Sum: 2us 99% C.I. 2us-2us Avg: 2us Max: 2us
Done Dumping histograms
young concurrent copying paused:    Sum: 178us 99% C.I. 178us-178us Avg: 178us Max: 178us
young concurrent copying freed-bytes: Avg: 2350KB Max: 2350KB Min: 2350KB
Freed-bytes histogram: 2240:1
young concurrent copying total time: 29.571ms mean time: 29.571ms
young concurrent copying freed: 15831 objects with total size 2350KB
young concurrent copying throughput: 545897/s / 79MB/s  per cpu-time: 89144888/s / 85MB/s
Average minor GC reclaim bytes ratio 490.655 over 1 GC cycles
Average minor GC copied live bytes ratio 0.00110673 over 820 minor GCs
Cumulative bytes moved 1695544
Cumulative objects moved 35948
Peak regions allocated 253 (63MB) / 1024 (256MB)
Total time spent in GC: 29.571ms
// GC的吞吐量
Mean GC size throughput: 76MB/s
Mean GC object throughput: 535288 objects/s
Total number of allocations 66740
Total bytes allocated 4065KB
Total bytes freed 2310KB
Free memory 23MB
Free memory until GC 23MB
Free memory until OOME 254MB
Total memory 25MB
Max memory 256MB
Zygote space size 1716KB
Total mutator paused time: 178us
Total time waiting for GC to complete: 4.689us
// GC发生的次数
Total GC count: 1
// GC消耗的时间
Total GC time: 29.571ms
// 阻塞GC发生的次数 阻塞GC执行之时会暂停其他的线程
Total blocking GC count: 0
// 阻塞GC消耗的时间
Total blocking GC time: 0
Histogram of GC count per 10000 ms: 0:1
Histogram of blocking GC count per 10000 ms: 0:1
Native bytes total: 18441048 registered: 61304
Total native bytes at last GC: 18543792
/system/framework/oat/arm64/android.hidl.base-V1.0-java.odex: quicken
/system/framework/oat/arm64/android.hidl.manager-V1.0-java.odex: quicken
/data/app/com.tiano.anrdemo-VyqkZUePQCFk45qOWaBtzw==/oat/arm64/base.odex: quicken
/system/framework/oat/arm64/gson.odex: speed
/system/framework/oat/arm64/org.apache.http.legacy.odex: speed-profile
/data/dalvik-cache/arm64/system@app@MiuiContentCatcher@MiuiContentCatcher.apk@classes.dex: speed
/data/dalvik-cache/arm64/system@app@CatcherPatch@CatcherPatch.apk@classes.dex: speed
Current JIT code cache size: 20KB
Current JIT data cache size: 13KB
Current JIT mini-debug-info size: 30KB
Current JIT capacity: 64KB
Current number of JIT JNI stub entries: 0
Current number of JIT code cache entries: 36
Total number of JIT compilations: 36
Total number of JIT compilations for on stack replacement: 0
Total number of JIT code cache collections: 0
Memory used for stack maps: Avg: 127B Max: 944B Min: 16B
Memory used for compiled code: Avg: 558B Max: 4016B Min: 4B
Memory used for profiling info: Avg: 222B Max: 7776B Min: 24B
Start Dumping histograms for 72 iterations for JIT timings
Compiling:  Sum: 17.737ms 99% C.I. 142us-2256us Avg: 492.694us Max: 2360us
Generate JIT debug info:    Sum: 1.078ms 99% C.I. 16us-45us Avg: 29.944us Max: 45us
TrimMaps:   Sum: 744us 99% C.I. 7us-94us Avg: 20.666us Max: 94us
Done Dumping histograms
Memory used for compilation: Avg: 63KB Max: 443KB Min: 15KB
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=5000
ProfileSaver total_ms_of_work=0
ProfileSaver max_number_profile_entries_cached=0
ProfileSaver total_number_of_hot_spikes=0
ProfileSaver total_number_of_wake_ups=0suspend all histogram:  Sum: 70.533ms 99% C.I. 1.306us-1212.159us Avg: 46.834us Max: 10430us
DALVIK THREADS (14):
//“Signal Catcher”负责接收和处理kernel发送的各种信号，例如SIGNAL_QUIT、SIGNAL_USR1等就是被该线程
//接收到并处理的，traces.txt 文件中的内容就是由该线程负责输出的，可以看到它的状态是RUNNABLE.
"Signal Catcher" daemon prio=5 tid=5 Runnable| group="system" sCount=0 dsCount=0 flags=0 obj=0x13f00408 self=0x7a8267ac00| sysTid=3562 nice=0 cgrp=default sched=0/0 handle=0x7a8f3e2d50| state=R schedstat=( 3092811 116928 6 ) utm=0 stm=0 core=5 HZ=100| stack=0x7a8f2ec000-0x7a8f2ee000 stackSize=991KB| held mutexes= "mutator lock"(shared held)native: #00 pc 0000000000411990  /apex/com.android.runtime/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*, bool)+140)native: #01 pc 00000000004f91f4  /apex/com.android.runtime/lib64/libart.so (art::Thread::DumpStack(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool, BacktraceMap*, bool) const+512)(no managed stack frames)
//线程名(“main”)，线程优先级(“prio=5”)，线程id(“tid=1”)，线程状态(Sleeping),比较常见的状态还有Native、Waiting；Native代表执行JNI代码
"main" prio=5 tid=1 Sleeping
//线程所处的线程组 （“main”），线程被正常挂起的次处（“sCount=1”），线程因调试而挂起次数（”dsCount=0“），当前线程所关联的java线程对象（”obj=0x762433c8“）以及该线程本身的地址（“0x7a9b069c00”）| group="main" sCount=1 dsCount=0 flags=1 obj=0x762433c8 self=0x7a9b069c00
//显示线程调度信息，分别是该线程在linux系统下得本地线程id （“ sysTid=3551”），线程的调度有优先级（“nice=-10”），调度策略（sched=0/0），优先组属（“cgrp=default”）以及 处理函数地址（“handle=0x7b21139ed0”）；| sysTid=3551 nice=-10 cgrp=default sched=0/0 handle=0x7b21139ed0
// 显示更多该线程当前上下文，分别是调度状态（从 /proc/[pid]/task/[tid]/schedstat读出）（“schedstat=( 107710942 40533261 131 )”），以及该线程运行信息 ，
// 它们是线程用户态下使用的时间值(单位是jiffies）（“utm=4”）， 内核态下得调度时间值（“stm=6”），以及最后运行改线程的cup标识（“core=2”）；| state=S schedstat=( 227596660 50698067 328 ) utm=14 stm=7 core=7 HZ=100
//表示线程栈的地址（“stack=0x7fcdc85000-0x7fcdc87000”）以及栈大小（“stackSize=8192KB”）| stack=0x7fcdc85000-0x7fcdc87000 stackSize=8192KB| held mutexes=
//  下面是线程的调用栈信息，也是分析ANR的核心所在。at java.lang.Thread.sleep(Native method)- sleeping on <0x07e7086e> (a java.lang.Object)at java.lang.Thread.sleep(Thread.java:440)- locked <0x07e7086e> (a java.lang.Object)at java.lang.Thread.sleep(Thread.java:356)at com.tiano.anrdemo.MainActivity$2.run(MainActivity.java:28)at android.os.Handler.handleCallback(Handler.java:883)at android.os.Handler.dispatchMessage(Handler.java:100)at android.os.Looper.loop(Looper.java:224)at android.app.ActivityThread.main(ActivityThread.java:7560)at java.lang.reflect.Method.invoke(Native method)at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:539)at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:950)......//JDWP线程是支持虚拟机调试的线程，daemon表示守护进程，不需要关心
"ADB-JDWP Connection Control Thread" daemon prio=0 tid=11 WaitingInMainDebuggerLoop| group="system" sCount=1 dsCount=0 flags=1 obj=0x13f00570 self=0x7a9b19cc00| sysTid=3563 nice=0 cgrp=default sched=0/0 handle=0x7a8f2e5d50| state=S schedstat=( 2208022 1284791 21 ) utm=0 stm=0 core=4 HZ=100| stack=0x7a8f1ef000-0x7a8f1f1000 stackSize=991KB| held mutexes=kernel: (couldn't read /proc/self/task/3563/stack)native: #00 pc 00000000000c14e8  /apex/com.android.runtime/lib64/bionic/libc.so (__ppoll+8)native: #01 pc 000000000007db40  /apex/com.android.runtime/lib64/bionic/libc.so (poll+88)native: #02 pc 0000000000008e24  /apex/com.android.runtime/lib64/libadbconnection.so (adbconnection::AdbConnectionState::RunPollLoop(art::Thread*)+824)native: #03 pc 000000000000721c  /apex/com.android.runtime/lib64/libadbconnection.so (adbconnection::CallbackFunction(void*)+1076)native: #04 pc 00000000000d6cb0  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36)native: #05 pc 0000000000074eac  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)(no managed stack frames)
......
//Binder线程是进程的线程池中用来处理binder请求的线程
"Binder:3551_1" prio=5 tid=13 Native| group="main" sCount=1 dsCount=0 flags=1 obj=0x13f00660 self=0x7a9b1b1c00| sysTid=3568 nice=0 cgrp=default sched=0/0 handle=0x7a8ecc6d50| state=S schedstat=( 6153126 14238958 22 ) utm=0 stm=0 core=0 HZ=100| stack=0x7a8ebd0000-0x7a8ebd2000 stackSize=991KB| held mutexes=kernel: (couldn't read /proc/self/task/3568/stack)native: #00 pc 00000000000c14a4  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)native: #01 pc 000000000007bb2c  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+132)native: #02 pc 00000000000590ac  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+244)native: #03 pc 0000000000059288  /system/lib64/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+24)native: #04 pc 0000000000059a60  /system/lib64/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+64)native: #05 pc 000000000007fb8c  /system/lib64/libbinder.so (android::PoolThread::threadLoop()+24)native: #06 pc 00000000000135f0  /system/lib64/libutils.so (android::Thread::_threadLoop(void*)+328)native: #07 pc 00000000000c4cb8  /system/lib64/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+140)native: #08 pc 00000000000d6cb0  /apex/com.android.runtime/lib64/bionic/libc.so (__pthread_start(void*)+36)native: #09 pc 0000000000074eac  /apex/com.android.runtime/lib64/bionic/libc.so (__start_thread+64)(no managed stack frames)

traces.txt内容较多，可以看下内容中我的部分注释；

首先，我们可以根据发生ANR的app包名和时间能确定ANR日志的地方，通常是再traces内容的最上面。

然后ANR必然是主线程异常，我们可以找到"main"线程部分，查看main线程相关状态。

可以很明确的看到主线程sleeping了，通常在多线程开发中，比较容易遇到的是blocked状态导致的ANR

其次我们可以继续找到下面的线程调用栈信息
这块我们就比较熟悉，和查看普通的异常一样，可以很明确的知道ANR 发生在MainActivity 28行处，原因是Thread.sleep()，此时我们再回到上面自己的代码层面，结果已经很明确。

当然，实际开发中的ANR通常不会这么简单，有些也没那么容易分析，这个就需要大家通过此篇文章的借鉴，结合实际开发多分析，多优化来增长自己的能力。

线程状态

对于上述线程状态，相对于java线程状态，Linux细化了很多状态，这样更便于分析当前的状态。

java中的线程和操作系统内核中的线程并不是等价关系。他们之间存在着映射关系，对Android来说，java中的线程和内核的线程是一对一关系。