📚 课程目录第3章 ANR日志分析

ANR日志分析：trace文件结构、关键信息解读

说起来，我入行头两年，最怕的就是凌晨被叫起来看ANR。那时不懂trace文件，看到一堆线程堆栈就头大。后来慢慢摸出门道，发现这东西其实就是一本「案发现场的口供」——谁在干什么、被什么卡住了，写得清清楚楚。

这篇文章，我把个人经验揉碎了讲。你按这个思路去读trace，不会再觉得那是天书。

trace文件长什么样？

ANR发生时，系统会dump出所有线程的调用栈。文件名叫traces.txt，通常放在/data/anr/下。你可以用adb pull拉出来。

adb root
adb remount
adb pull /data/anr/traces.txt .

打开文件，你会发现内容分两大块：进程头部信息 和 线程列表。我刚开始看时，总是先扫头部，再细看主线程。

头部信息：一瞥全局

头部记录了系统状态和进程概览。比如这样一段：

----- pid 12345 at 2024-08-20 14:30:45 -----
Cmd line: com.example.myapp
JNI: CheckJNI is OFF; DDM is ON
Build fingerprint: 'google/...'
ABI: 'arm64-v8a'
...

重点关注几个字段：

pid —— 进程ID，确定是哪个应用
Cmd line —— 包名，确认没抓错进程
Build fingerprint —— 系统版本，有些ANR是系统bug
ABI —— 32位还是64位，影响库兼容性

有一次我排查一个ANR，发现cmd line后面跟着一堆content://的URI，当时就猜到是ContentProvider没准备好。顺着这个线索，很快找到问题。

主线程堆栈：ANR的核心线索

往下翻，你会看到"main" prio=5 tid=1开头的一段。这就是主线程的堆栈。我习惯先看最底部的at行：

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x...
  | sysTid=12345 nice=-2 cgrp=default sched=0/0 handle=0x...
  | state=S schedstat=( 0 0 0 ) utm=0 stm=0 core=0
  #00 pc 00000000  /system/lib64/libc.so (__epoll_pwait+...)
  #01 pc 00000000  /system/lib64/libutils.so (Looper::pollOnce+...)
  #02 pc 00000000  /system/lib64/libgui.so (SurfaceFlinger::...)
  ...
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:336)
  at android.os.Looper.loop(Looper.java:196)
  at android.app.ActivityThread.main(ActivityThread.java:...)

关键点：

线程状态：Native、Runnable、Blocked、Waiting。如果是Native，说明在调用底层代码；如果是Blocked，大概率是锁竞争。
堆栈深度：从nativePollOnce到Looper.loop，这是正常的消息循环。如果主线程卡在别的方法，比如View.onDraw或Service.onCreate，那就要重点排查。
系统调用：__epoll_pwait表示在等事件，通常不是问题。但如果是futex或__ioctl，可能是有IPC阻塞。

注意： 我看到很多人一上来就盯着主线程堆栈，却忽略了其他线程。有时候主线程是在等子线程的结果，或者被全局锁卡住。多线程联动分析，才能看到全貌。

子线程堆栈：锁和等待链

每个线程都有类似的格式。我重点关注几个东西：

线程名称："pool-1-thread-1"、"Binder:12345_1"，能看出是线程池还是Binder线程。
锁信息：从Android 7开始，trace里会附加锁图。比如：

  waiting to lock <0x0c4f...> (a java.lang.Object) held by thread 5
  at com.example.MyClass.myMethod(MyClass.java:100)
  - waited on <0x0c4f...> (a java.lang.Object)

这表示线程3在等线程5持有的锁。如果线程5也在等另一个锁，就形成了死锁链。我曾经遇到过一个经典死锁：主线程等子线程的锁，子线程等Binder线程的锁，Binder线程又在等主线程的锁。三条线程互相等，系统直接给ANR。

我的经验： 遇到锁相关ANR，别急。先看哪个线程持有锁时间最长，然后再查它为什么慢。很多时候是锁内做了IO或网络操作。

CPU使用率和schedstat

每个线程的schedstat字段包含三个数字：运行时间 / 等待时间 / 上下文切换次数。单位是纳秒。比如：

schedstat=( 1234567890 987654321 100 )

解读方法：

运行时间长但等待时间短 → 线程一直在计算，可能是死循环
运行时间短但等待时间长 → 线程在等资源，比如锁或IO
上下文切换次数多 → 可能频繁锁争用或线程调度问题

我记得有一次，一个子线程的上下文切换次数高达几百万，运行时间却很少。明显是锁竞争太激烈。后来改成读写锁，ANR就消失了。

Binder通信统计

在进程头部区域，有时候能看到Binder信息：

Binder: 12345 (12345) outstanding transactions:
  transaction 0x1234 from pid 6789 (com.other.app)
  started at 1234567890

这表示当前进程有未完成的Binder调用。如果主线程正在等这个Binder返回，而对方进程没反应，ANR就来了。这类问题通常要查对方进程。

如何快速定位ANR原因？

我总结了一个四步法：

看主线程：找到"main" tid=1的堆栈，确认卡在哪。
看锁关系：如果主线程是Blocked，搜waiting to lock，找到持有锁的线程。
查CPU和schedstat：判断是线程在忙还是等资源。
检查Binder：如果有outstanding transaction，追查对方进程。

这套方法，我在多个项目里验证过。最快的一次，只用2分钟就定位到一个ContentProvider死锁。

  核心原则： trace文件不是魔法，它只是按时间冻结的「快照」。你看到的是ANR发生那一刻的状态。但很多时候，原因可能在更早的时间点。所以，多拿几个trace对比，或者结合logcat一起看。

trace文件结构全景图

下面这张图，把trace文件的整体结构和关键信息串起来了。你以后打开trace文件，可以按这个思路走。

一些避坑提醒

我在团队里分享trace分析时，大家常问几个问题：

Q：trace里主线程卡在nativePollOnce，是不是说明它在做耗时操作？
A：不一定。nativePollOnce 是Looper在等待新消息，正常状态。你得看它等了多久 —— 结合schedstat的等待时间判断。如果等待时间异常长，那可能是消息队列里没消息，但ANR阈值到了，这种情况通常是系统问题或别的线程卡住了主线程。

曾经有一个坑： 我分析一个ANR，主线程堆栈显示在onCreate里做数据库查询。当时觉得是查询慢，后来发现是ContentResolver在等另一个进程的ContentProvider，而那个进程被系统冻结了。所以，别只看自己的代码，也要看系统服务的堆栈。

再一个，trace文件里有时会包含多个进程的信息。你拿到后，记得先确认pid是不是你想要的。我曾有一次拿错了，分析半天才发现是系统服务的问题。

好了，trace文件结构就这些。你下次遇到ANR，按这个框架去拆解，不会出大错。