📚 课程目录第2章 ANR日志获取与分析

第2章：ANR日志获取与分析——trace文件、logcat、dumpsys实战

说到ANR排查，我个人的第一反应永远是——先看日志。你想想看，没有日志，就像医生不给病人拍片子，全靠猜。Android系统其实挺厚道的，它会把ANR发生时的现场快照全都记录下来。这一章我们就来聊聊怎么拿到这些“病历本”，以及怎么看懂它。

2.1 trace文件——ANR的第一手现场

当系统检测到ANR时，它会把涉及到的所有线程的堆栈信息dump到 /data/anr/traces.txt 文件中。这个文件就是我们的“案发现场”。

获取方式： 使用adb pull命令拉取到本地。

adb shell ls /data/anr/           # 先看看有哪些文件
adb pull /data/anr/traces.txt .  # 拉到当前目录
# 如果没有root权限，尝试：
adb bugreport bugreport.zip      # 从bugreport里也能拿到

嗯，这里要注意：Android 10以上的设备默认只能抓取自己应用的trace文件。如果你不是系统应用，需要先给自己的app加上 READ_EXTERNAL_STORAGE 权限，或者使用 android:debuggable="true" 的debug版本。

怎么看trace文件？ 我习惯一打开就直接搜索 "main"（主线程），然后看它卡在哪个方法上。举个例子：

----- pid 12345 at 2024-05-20 10:30:45 -----
Cmd line: com.example.myapp

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x756b4938
  | sysTid=12345 nice=0 cgrp=default sched=0/0 handle=0x7f89c09e50
  at com.example.MyService.onStartCommand(MyService.java:25)
  - waiting to lock <0x0a6c1234> (a java.lang.Object) held by thread "binder:12345_1"
  at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:4567)
  ...

看到 Blocked 状态和 waiting to lock 了吗？这说明主线程在等一把锁。持有锁的那个线程是 binder:12345_1。直接锁竞争导致的ANR，非常典型。我曾经遇过一个项目，就是因为Binder线程池满了，主线程要等一个service的锁，堵了十几秒。

trace文件关键字段速查表

字段	含义	排查价值
tid=1	主线程	主线程卡住就是ANR
state	Runnable/Blocked/Sleeping	Runnable-正在跑，Blocked-等锁，Sleeping-等时间
at ...	当前执行的方法	直接定位卡点
waiting to lock	等待的锁对象	锁竞争分析
held by thread	持有锁的线程	找谁在阻塞

避坑指南： 我曾经遇到过一次，trace文件里主线程明明显示Runnable，可ANR时间到了它就是没执行完。后来发现是CPU被其他进程抢占了——也就是“CPU饥饿”。只看trace文件可能会漏掉。所以一定要结合后续的logcat和dumpsys一起看。

2.2 logcat——系统日志里的关键线索

ANR发生时，logcat里会有专门的日志输出。你搜关键词 "ANR" 就能找到。

adb logcat -b main -b events -b system -v time | grep -E "ANR|am_anr|ActivityManager"

为什么我同时抓三个buffer？main 是应用日志，events 有系统事件如 am_anr，system 包含ActivityManager的输出。三者对齐时间戳，才能还原完整现场。

举个例子，logcat中你会看到类似这样的行：

05-20 10:30:45.123  1234  5678 I am_anr  : [0,12345,com.example.myapp,564078328,Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window...)]

这里的信息量很大：12345是pid，Input dispatching timed out说明是输入事件响应超时（5秒）。如果是 Broadcast of Intent，那是广播超时（10秒）。不同的超时类型，排查方向完全不同。

常见ANR超时类型一览

logcat关键词	超时类型	时长	常见原因
Input dispatching timed out	输入事件	5秒	主线程阻塞
Broadcast of Intent	广播接收	10秒	onReceive执行业务
Service Timeout	服务启动/绑定	20秒	Service.onCreate太慢
ContentProvider Timeout	内容提供者	10秒	Provider慢或死锁

我在一个项目里排查广播ANR时，logcat里明确写了 Broadcast of Intent，然后trace文件显示主线程在做数据库写操作。但数据库写为什么会这么慢？后来用dumpsys查了磁盘IO，发现是因为同时有好几个线程在大量读写同一个文件，导致io wait飙升。你看，又是多重工具配合的结果。

2.3 dumpsys——系统内部状态的X光

dumpsys能帮我们拿到更底层的系统状态。常用的几个命令：

# 查看当前所有进程的CPU和时间信息
adb shell dumpsys cpuinfo

# 查看dropbox里的ANR记录（持久化保存）
adb shell dumpsys dropbox --print data_app_anr

# 查看窗口焦点和输入分发状态
adb shell dumpsys window windows

# 查看ActivityRecord和进程oom_adj
adb shell dumpsys activity processes

dumpsys cpuinfo 能做啥？你想想看，如果ANR发生时主线程是Runnable状态，但CPU信息显示它在User态跑了4.9秒，那么基本可以排除CPU饥饿。但如果显示它只跑了0.1秒，其他时间都在Wait，说明问题在IO或锁。

dumpsys dropbox 我最常用。它保存了所有ANR的完整dump，包括trace和线程状态。这个命令不需要root也能跑。而且它还记录了ANR发生时的系统负载信息：

adb shell dumpsys dropbox --print data_app_anr | head -200

输出里会有一段类似于：

Subject: ANR in com.example.myapp (com.example.myapp/.MyActivity)
CPU usage from 123456ms to 123456ms ago:
  45% 12345/com.example.myapp: 30% user + 15% kernel / faults: 200 minor 50 major
  85% TOTAL: 40% user + 20% kernel + 25% iowait

看到 25% iowait 了吗？这说明整个系统的IO负载很高。如果应用自己的CPU占用并不高，但总CPU的iowait很高，那就要怀疑是不是其他进程或者系统服务在搞事情。

实战技巧： 我个人习惯在做ANR排查时，先执行一个“日志三件套”命令，一次性把关键信息都抓回来：

adb shell dumpsys cpuinfo > cpu.txt
adb shell dumpsys dropbox --print data_app_anr > anr_log.txt
adb shell dumpsys activity processes > procs.txt

然后结合logcat和trace文件，四份材料放在一起对比时间戳分析。

2.4 实战：一次完整的多日志联合分析

说个真实案例。有一个用户反馈App在点击某个按钮后卡死，持续好几秒。我们拿到的日志如下：

trace文件：主线程在 onClick 方法里调用 BitmapFactory.decodeFile，状态是 Runnable。没有看到锁等待。奇怪吧？
logcat：搜索ANR，显示 Input dispatching timed out (Waiting because the touched window is frozen)，时间戳恰好是用户点击后的第5秒。
dumpsys cpuinfo：ANR发生时，系统总iowait高达30%，而App进程CPU只有5%。
dumpsys dropbox：记录了ANR时磁盘读写情况，显示在ANR前几秒内，有大量的 major page faults。

综合判断：主线程虽然没被锁，但它在解码一个超大图片（内存不足导致频繁磁盘交换），加上系统IO繁忙，导致解码耗时超过5秒。所以是IO问题带来的“假卡死”。

避坑指南： 我曾经以为Runnable就代表CPU正在执行，其实不是。Runnable只是表示“可以被调度”，但可能因为CPU被其他进程抢走、或者在等IO（内核态Wait）而实际上没跑。所以一定要看CPU时间占比，别只看线程状态。

2.5 总结一下核心要点

trace文件：看主线程堆栈，定位卡点方法。注意线程状态和锁关系。
logcat：搜“ANR”/“am_anr”，确认超时类型（输入/广播/服务/provider）。
dumpsys cpuinfo：看进程CPU和iowait，判断是CPU耗尽还是IO瓶颈。
dumpsys dropbox：获取持久化的ANR记录，包含系统负载上下文。
多工具联合分析：单一日志容易误判，至少两份日志对时间戳才能下结论。