第3章:ANR日志文件结构——traces.txt、events.log、main log

搞多媒体启动卡顿,第一步不是看代码,而是看日志。这就像医生看病,先看化验单。我自己做性能优化这么多年,最怕听到一句话:“没日志,你帮我查一下。”——没日志我真没法查。今天就聊聊ANR的三份核心日志文件,它们各自长什么样,以及我怎么从中挖出线索。

3.1 三份日志,各司其职

一个完整的ANR场景,系统会同时吐出三类日志。用表格一列就清楚了:

日志文件存放路径主要用途
traces.txt/data/anr/traces.txt记录所有线程的堆栈现场,主线程卡在哪一目了然
events.log/data/system/dropbox/ 或 event log记录系统事件时间戳,比如输入事件、服务超时、进程状态变化
main log(logcat)adb logcat 实时抓取或 /data/log/ 历史文件应用自身日志 + 系统日志,包含ANR发生时打印的关键信息

这三份文件我一般会同时拉下来。先看哪个?嗯,不一定。有时traces.txt直接告诉我主线程在等一个锁,但不知道锁被谁持有。这时就得翻events.log,看那个线程是不是卡在某次Binder调用里。再不行就查main log,看ANR之前有没有内存抖动或网络超时日志。

3.2 traces.txt:线程堆栈的“尸体报告”

traces.txt是ANR发生时系统自动生成的。位置固定:/data/anr/traces.txt。但这个文件会被覆写,你最好在ANR发生后第一时间把它拉出来。我以前犯过这个错:先清了缓存再拉日志,结果traces.txt已经被新ANR覆盖了——白忙一场。

⚠️ 注意:多用户设备下 traces.txt 可能只存在第一个用户空间。建议用 adb shell ls -l /data/anr/ 先看一眼有没有这个文件。

traces.txt 内容大致分成三部分:

  • 系统概要头:ANR发生的时间、进程名、pid、CPU使用率、负载情况。
  • 主线程堆栈:通常以“main”开头,看它的调用链。
  • 其他线程堆栈:包括Binder线程、AsyncTask线程等。有时“凶手”不在主线程,而在另一个子线程死锁了,导致主线程等不到结果。

举个例子,我见过一个多媒体启动卡顿,traces里主线程停在 android.os.MessageQueue.nativePollOnce。很多人一看就以为主线程在空等,其实它是Handler在等消息。真正的问题是哪里?看它前面的消息处理链。如果你发现主线程在等一个Service连接,而那个Service的onBind也在等同一个锁,那就死锁了。

我的经验:拿到traces.txt后,先搜“main”找到主线程栈。然后看最上面的几行——那才是当前正在执行的函数。如果看到“nativePollOnce” + “MessageQueue” + “Looper.loop”,说明主线程刚空闲下来,那ANR原因可能不在当前时间点,而是之前某个消息处理太久了。这时候你需要翻events.log看时间线。

3.3 events.log:时间线的“监控录像”

events.log不叫一个文件,其实是一堆dropbox文件。系统会把每个ANR事件单独存一个文件,命名类似 system_app_anr@时间戳.txt。路径在 /data/system/dropbox/ 下。我推荐用 adb shell dumpsys dropbox --print data_app_anr 直接按类型打印出来,省得一个个翻文件夹。

events.log里藏着什么?说白了就是时间戳大集合。它会记录:

  • 输入事件(触摸、按键)的dispatch时间和超时时间
  • Service、Broadcast、Provider的超时起止时间
  • 进程的CPU时间片使用情况
  • 系统认为“该响应但没响应”的时刻

我自己排查时,习惯把ANR发生的精确时间(从main log里拿)和events.log里的时间戳做对比。如果有多个ANR,events.log还能帮你判断哪个是真正的“第一次”——有时候用户连续卡死,后面的ANR都是前面问题导致的连锁反应。

💡 技巧:用 adb shell dumpsys dropbox --print data_app_anr | grep -A 20 "Broadcast of Intent" 快速定位广播超时相关的日志。多媒体很多启动卡顿都是因为广播阻塞。

3.4 main log:应用和系统的“录音室母带”

main log就是logcat抓到的日志。它包含应用自己的日志(Log.i/d/w/e)和系统日志(ActivityManager、InputManager等)。ANR发生时,系统会打印如下关键行:

// 关键行1:ANR弹窗提示
ActivityManager: ANR in 包名 (进程名)
CPU usage from 0ms to 5000ms later:
  ...

// 关键行2:输入事件超时
InputDispatcher: Application is not responding: AppWindowToken{...}
  Waiting because the focused window has not been focused.

// 关键行3:具体原因分类
ActivityManager: Reason: Input dispatching timed out (Waiting because no window has focus...)
  or: Reason: Executing service 包名/.MyService
  or: Reason: Broadcast of Intent { act=com.example.ACTION }

这里我特别看重Reason那一行。它告诉你ANR是哪一类:输入超时、Service超时、还是Broadcast超时。多媒体启动卡顿以Service超时和Broadcast超时最常见。比如你有个后台播放Service在主线程绑定了MediaPlayer,结果onCreate里做了网络请求,卡了10秒,那肯定ANR。

有一次我遇到一个诡异问题:logcat里没有任何ANR打印,但是用户反馈应用卡死。后来发现是logcat缓冲区满了,ANR日志被挤掉了。所以我现在的习惯是:先 adb logcat -G 16M 把缓冲区设大,再复现问题。千万别省这一步。

3.5 三份日志的协作分析流程

把三份日志串起来,才叫真正的ANR分析。我自己总结了一个“三步走”:

  1. 看main log:确定ANR发生时间、进程、类型(输入/Service/Broadcast)。把时间点记下来。
  2. 看events.log:在同一个时间窗口内,看系统记录的进程CPU使用率、事件分发延迟。尤其注意“dispatch timed out”的出现时间。
  3. 看traces.txt:找到对应时间的线程堆栈,确认主线程当时在做什么。

这三者就像侦探的三件套:动机(main log)、目击证词(events.log)、现场痕迹(traces.txt)。缺一个都可能误判。

💡 我习惯把三个日志的时间戳都统一到同一个时区(比如都是UTC+8)。不然一个用UTC,一个用本地时间,对起来特别痛苦。
ANR日志分析三件套 traces.txt events.log main log 主线程堆栈 其他线程堆栈 输入事件超时 Service/Broadcast超时 ANR Reason 行 CPU 使用情况 协作分析流程 ① main log 定位时间+类型 ② events.log 校验时间线+CPU ③ traces.txt 锁定线程堆栈

3.6 一个真实案例的日志对比

给你看一个我实际处理过的多媒体启动ANR的日志片段(脱敏处理):

// main log 中的关键行
06-15 10:23:45.123  1234  5678 I ActivityManager: ANR in com.example.player
06-15 10:23:45.123  1234  5678 I ActivityManager: Reason: Input dispatching timed out (Waiting because no window has focus...)

// events.log 中的内容(已简化)
Dropbox: data_app_anr@1623745425123
  Subject: Input dispatching timed out
  Timeout waiting because no window has focus
  CPU usage: 5% user, 3% kernel, 92% iowait

// traces.txt 中的主线程栈
"main" prio=5 tid=1 Native
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:336)
  at android.os.Looper.loop(Looper.java:183)
  at android.app.ActivityThread.main(ActivityThread.java:7656)

看到92%的iowait了吗?这说明CPU在疯狂等磁盘I/O。主线程虽然看似在消息循环,但实际上是前一个消息处理时触发了大量的文件操作导致系统卡住了。我继续往下查traces.txt里的其他线程,发现一个MediaExtractor在读文件时发生了Binder调用等待。最终定位到存储碎片严重,优化后启动时间从6秒降到1.2秒。

这个案例里,如果只看traces.txt,你会误以为主线程没干活。但加上events.log的CPU使用率,就能看出问题不在代码逻辑,而在I/O瓶颈。所以我说,三份日志缺一不可。

3.7 实践建议:如何快速抓取这三份日志

你不会想在客户现场手忙脚乱吧?我推荐一个脚本,加到你的ADB工具包里:

#!/bin/bash
# 抓取ANR日志,时间戳命名
TIMESTAMP=$(date +%Y%m%d_%H%M%S)
mkdir -p anr_$TIMESTAMP
adb shell dumpsys dropbox --print data_app_anr > anr_$TIMESTAMP/events.log
adb shell cat /data/anr/traces.txt > anr_$TIMESTAMP/traces.txt
adb logcat -d -b main -v time > anr_$TIMESTAMP/main.log
echo "Done: anr_$TIMESTAMP/"
💡 注意:有些设备 /data/anr/traces.txt 需要root权限才能读取。如果拿不到,可以尝试 adb shell ls -l /data/anr/ 查看权限;或者用 adb bugreport 打包所有日志,里面包含traces.txt的副本。