4. 堆栈文件结构解读：CPU采样、线程列表、锁信息、系统服务调用链

4.1 现象识别：当ANR发生时，我们看到了什么？

ANR发生时，系统会在 /data/anr/traces.txt 中生成一份“死亡诊断书”。但原始日志常包含数千行信息，其中隐藏着定位主线程阻塞的关键线索。

典型错误认知： 认为 traces.txt 只有主线程堆栈有用。实际上，CPU采样率、锁等待链、Binder调用队列 才是揪出根因的核心。

排查故障树（顶部）：

  • 主线程是否在 执行耗时方法（如文件IO、网络请求） → 查看主线程堆栈
  • 主线程是否在 等待锁（blocked on monitor） → 查看锁信息 & 锁持有者线程
  • 主线程是否卡在 Binder调用 → 查看系统服务调用链
  • CPU是否被其他线程 占满导致调度延迟 → 查看CPU采样汇总

4.2 数据采集：从traces.txt中提取四大要素

以下是一个简化版traces.txt样例（注：真实文件更冗长，但结构一致）：

----- pid 12345 at 2025-04-01 10:15:30 -----
Cmd line: com.example.anrdemo
Build fingerprint: '...'
ABI: 'arm64-v8a'

JNI: CheckJNI is off; workarounds are off; ...
DALVIK THREADS (12):
"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x... self=0x...
  | sysTid=12345 nice=0 cgrp=default sched=0/0 handle=0x...
  | stateS schedstat=( 123456789 987654321 500 ) utm=150 stm=50 core=4 HZ=100
  | stack=0x...-0x... stackSize=8MB
  | held by tid=2 (Binder:12345_1)
  at com.example.anrdemo.MainActivity.onClick(MainActivity.java:25)
  - waiting to lock <0x...> (a java.lang.Object) held by tid=2 (Binder:12345_1)
  at ...

"Binder:12345_1" prio=5 tid=2 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x... self=0x...
  | sysTid=12346 nice=0 cgrp=default sched=0/0 handle=0x...
  | stateS schedstat=( 987654321 123456789 800 ) utm=100 stm=200 core=5 HZ=100
  | stack=0x...-0x... stackSize=8MB
  | held by tid=1 (main)
  at android.os.BinderProxy.transactNative(Native Method)
  - waiting to lock <0x...> (a java.lang.Object) held by tid=1 (main)
  at ...

"RenderThread" prio=5 tid=3 Runnable
  ...

CPU usage: 12345ms user, 23456ms system, 34567ms iowait
  CPU load average: 4.5 / 6.0 / 5.0
  // 全局CPU使用率

DALVIK THREADS CPU TIME (top 5):
  "Binder:12345_1" : 4500ms (user=3000ms sys=1500ms)
  "main" : 300ms (user=200ms sys=100ms)
  "RenderThread" : 200ms
  "FinalizerDaemon" : 50ms
  ...

4.3 原因定位：逐层解码四大要素

4.3.1 CPU采样 —— 判断是否“被饿死”

CPU采样数据（schedstat、全局负载、线程CPU时间）帮助我们回答：主线程是否真的在执行计算？还是被其他线程抢占导致长时间无法获取CPU？

指标含义判据示例值
schedstat (run time / wait time / timeslice)线程实际运行时间 / 等待调度时间 / 上下文切换次数若 run time < wait time 且 wait time 巨大 → 线程饥饿run=123ms wait=987ms → 被饿死
utm (user time) / stm (system time)用户态/内核态CPU时间（毫秒）主线程 utm+stm 极小 < 200ms，且整体ANR超时5s → 非计算型阻塞utm=150 stm=50 → 总计200ms，非CPU密集型
CPU负载平均值最近1/5/15分钟平均活跃线程数若load > 核数*0.7，整体系统繁忙load=4.5（4核CPU） → 轻度过载
线程CPU时间排名各线程消耗CPU时长若主线程排名靠后且时间极短，说明未获得调度main仅300ms，Binder线程4500ms → 主线程被饿死
实战口诀： 主线程CPU时间少 + 其他线程CPU时间极高 → 主线程被挤占；主线程CPU时间多但堆栈停在某方法 → 该方法是性能瓶颈。

4.3.2 线程列表 —— 定位死锁与资源竞争

每个线程的堆栈中隐藏着“waiting to lock”和“held by”信息。通过扫描所有线程，可以构建出锁等待图。

排查步骤：

  1. 找出所有状态为 Blocked 或 Waiting 的线程（尤其是main）。
  2. 记录每个线程正在等待的锁地址 以及 当前持有该锁的线程ID。
  3. 若发现循环等待（A等B、B等A），判定为死锁。
  4. 若主线程等待的锁被Binder线程长期持有，且Binder线程又在等待其他资源 → 锁竞争升级为ANR。

4.3.3 锁信息 —— 深入分析monitor与synchronized

以上述样例为例：

- waiting to lock <0x1234abcd> (a java.lang.Object) held by tid=2 (Binder:12345_1)

这表示主线程（tid=1）在等待对象锁0x1234abcd，而该锁当前被Binder线程（tid=2）持有。接着检查Binder线程堆栈，发现它也在等待另一个锁（可能是系统服务Binder调用）——形成锁依赖链。

常见陷阱： 不要只看主线程的锁等待，必须追溯锁持有者的堆栈，确认其为什么长时间不释放锁。有时持有者只是正在做一次慢速磁盘IO，但被锁链放大。

4.3.4 系统服务调用链 —— 识别Binder阻塞

系统服务（如ActivityManagerService、WindowManagerService）调用通常发生在Binder线程中。当主线程调用 bindService、startActivity 或访问ContentProvider时，会等待Binder返回。

关键线索：

  • 主线程堆栈中出现 android.os.BinderProxy.transactNative 或 android.os.Parcel.readException。
  • Binder线程堆栈中出现 com.android.server.am.ActivityManagerService.serviceDoneExecuting 等系统服务方法，且阻塞在内部锁上。
  • 系统服务的CPU时间也很高 → 服务端耗时。

故障树分支（Binder场景）：

主线程堆栈症状Binder线程堆栈症状根因修复方向
停在 transactNative停在 handleMessage 内部某耗时操作服务端处理慢异步化、缓存、缩小同步范围
停在 transactNative停在 waiting on condition 等待信号死锁或服务端线程池耗尽检查服务端锁、增加worker线程
停在 acquireProvider停在ContentProvider query 方法执行慢SQLContentProvider读写延迟优化SQL、使用异步ContentResolver

4.4 修复动作：基于解码结果的针对性方案

根据上述定位，可分类修复：

  1. CPU饥饿 → 降低高CPU线程优先级（如android:threadPriority）或使用AsyncTask.THREAD_POOL_EXECUTOR限制并发数；针对IO线程限制调度组。
  2. 锁竞争/死锁 → 减少同步块粒度，避免在锁内调用外部方法；使用ReentrantLock带超时，或改为并发容器。
  3. Binder调用延迟 → 将主线程的Binder调用移入工作线程（如使用IntentService、ViewModel+Coroutine）；若必须同步，则对服务端加入异步回调。
  4. 系统服务超时 → 应用层无法直接修复系统服务，但可以通过减少与服务端的交互频率，或预加载数据来降低触发概率。

4.5 复测：验证修复前后traces.txt变化

修复后，再次触发ANR场景，对比traces.txt中的关键指标：

  • 主线程状态从 Blocked 变为 Runnable 或 Native（合理短时）。
  • schedstat中的wait time大幅下降。
  • 锁等待链消失，不再出现“waiting to lock”或死锁循环。
  • Binder线程不再阻塞在主线程持有的锁上。

4.6 预防：建立堆栈定期监控与预警机制

将traces.txt解析自动化，纳入CI/CD流水线：

  • 定义检测规则：主线程wait time > 2s、任何线程deadlock检测、Binder调用响应时间阈值。
  • 在测试阶段收集traces.txt，解析并输出检测报告，阻止ANR代码合入。
  • 线上使用anr-watchdog库或BlockCanary类工具，提前捕获非ANR的卡顿（UI线程阻塞>2s）并输出类似堆栈。
// 伪代码：TracesAnalyzer解析规则
if (mainThread.state == "Blocked" && mainThread.waitTime > 2000) {
    lockOwner = extractHeldBy(mainThread.stack);
    if (lockOwner.stack.contains("BinderProxy.transactNative")) {
        report(BLOCKED_ON_BINDER_CALL);
    }
    if (hasDeadlock(allThreads)) {
        report(DEADLOCK);
    }
}
堆栈文件解码流程与四大要素诊断图 traces.txt 原始日志 ① CPU采样数据 ② 线程列表 ③ 锁等待信息 ④ Binder调用链 是否被饿死？ schedstat wait time >> run time 是否存在死锁？ 循环等待或锁竞争 等待谁？为什么？ 追溯锁持有者堆栈 服务端超时？ transactNative 阻塞 修复行动：针对根因实施 预防：自动化traces解析 & 卡顿监控 复测：对比修复前后堆栈指标

4.7 完整案例分析（合成日志）

背景： 某社交App在用户发帖时偶现ANR，traces.txt片段如下：

"main" prio=5 tid=1 Blocked
  at com.example.social.PostActivity.uploadImage(PostActivity.java:45)
  - waiting to lock <0x...> (a java.lang.Object) held by tid=10 (OkHttp Dispatcher)

"OkHttp Dispatcher" prio=5 tid=10 Runnable
  at okhttp3.internal.connection.RealCall.execute(RealCall.java:120)
  - locked <0x...> (a java.lang.Object)

CPU usage: 用户态92%, 系统态8%
  "OkHttp Dispatcher" user=3200ms sys=400ms
  "main" user=50ms sys=20ms

解码过程：

  1. CPU数据： 主线程CPU仅70ms（极低），OkHttp线程消耗3600ms → 主线程非计算瓶颈，被饿死或锁等待。
  2. 锁信息： 主线程等待 0x... 锁，该锁被OkHttp线程持有。
  3. 线程列表： OkHttp线程正在做网络请求（RealCall.execute），可能耗时较长（网络慢或线程池耗尽）。
  4. 根因： 主线程在 uploadImage 中使用了同步网络请求（OkHttp同步调用），且该锁被并发请求共享，导致主线程等待网络完成。
  5. 修复： 将 uploadImage 改为异步回调或使用 Coroutine 切换线程，移除共享锁。

复测： 修复后，traces.txt显示主线程状态为 Runnable 且schedstat wait时间 <50ms，无锁等待。

← 上一章 📖 返回目录 下一章 →