Android 7系统异常问题排查（八）系统追踪—Trace机制与性能诊断

系列目录第一篇异常机制全景图 | 第二篇Kernel Panic 与系统重启 | 第三篇Tombstone 机制 | 第四篇System Server Watchdog | 第五篇System Server 崩溃 | 第六篇ANR 机制 | 第七篇Java 层崩溃 | 第八篇Trace 机制 | 第九篇日志系统 | 第十篇实战方法论一、为什么需要 Trace 机制你可能遇到过这些场景用户反馈 App 滑动卡顿但 logcat 里没有任何异常日志系统启动慢但不知道卡在哪个阶段掉帧严重但无法定位是渲染慢还是 CPU 调度问题系统服务调用响应慢但不知道延迟发生在哪一端前几篇文章介绍的 tombstone、ANR、Watchdog 都是事后分析——异常已经发生我们只能从日志中还原现场。但很多问题如系统卡顿、掉帧、响应慢并不会触发明确的异常却严重影响用户体验。Trace 机制正是为了解决这类没有硬错误但有严重问题的场景。Trace 能回答的问题问题类型Trace 能提供的信息UI 卡顿每个帧的渲染耗时、哪些线程在竞争 CPU启动慢启动过程中各阶段耗时、Binder 调用延迟掉帧SurfaceFlinger 合成时间线、VSYNC 信号系统服务慢Binder 调用耗时、锁竞争、线程调度功耗异常CPU 频率分布、各进程的 CPU 时间片IO 阻塞磁盘读写耗时、I/O 调度延迟二、Trace 体系全景在 AOSP 7 中trace 体系分为三层┌──────────────────────────────────────────────┐ │ 用户态工具层 │ │ ├─ systrace (systrace.py) │ │ ├─ atrace 命令行工具 │ │ └─ perfettoAOSP 7 后引入暂不展开 │ ├──────────────────────────────────────────────┤ │ Framework 打点层 │ │ ├─ Trace.java (android.os.Trace) │ │ ├─ ATrace (native 层) │ │ └─ 各系统服务的 trace tag │ ├──────────────────────────────────────────────┤ │ 内核追踪层 │ │ ├─ ftrace (tracefs) │ │ ├─ tracepoint / kprobe / uprobe │ │ └─ trace_marker (用户态写入内核 trace buffer) │ └──────────────────────────────────────────────┘三、ftrace —— 内核追踪基础3.1 ftrace 是什么ftrace 是 Linux 内核内置的追踪框架通过tracefs文件系统暴露接口。它是 Android 所有 trace 工具的底层基础。3.2 挂载与结构# Android 中 ftrace 挂载在mount-ttracefs none /sys/kernel/tracing# 或旧版本mount-tdebugfs none /sys/kernel/debug# 关键目录结构/sys/kernel/tracing/ ├─ available_tracers# 可用的追踪器├─ current_tracer# 当前使用的追踪器├─ tracing_on# 1开启 0暂停├─ trace# 追踪结果输出├─ trace_marker# 用户态写入标记├─ events/# tracepoint 事件│ ├─ sched/# 调度事件│ ├─ binder/# Binder 事件│ ├─ power/# 电源管理事件│ └─... └─ options/# 追踪选项3.3 trace_marker 用户态打点这是连接用户态和内核态的重要桥梁——用户态通过向trace_marker文件写入特定格式的数据将标记注入内核 trace buffer// 用户态写入 trace 标记// frameworks/native/libs/utils/Trace.cppstaticvoidtraceInit(){// 打开 trace_marker 文件atrace_marker_fdopen(/sys/kernel/tracing/trace_marker,O_WRONLY);}voidATrace_begin(constchar*name){// 写入 B|pid|name 到 trace_markercharbuf[1024];snprintf(buf,sizeof(buf),B|%d|%s,getpid(),name);write(atrace_marker_fd,buf,strlen(buf));}voidATrace_end(){// 写入 E 到 trace_markerwrite(atrace_marker_fd,E,1);}关键设计通过简单的文件写入操作write()用户态代码就能将打点信息注入内核 trace buffer实现跨进程的精确时间同步。格式B|pid|name中的B表示 beginE表示 end。3.4 关键 tracepoint类别tracepoint用途调度sched/sched_switch线程切换找出 CPU 竞争调度sched/sched_wakeup线程被唤醒追踪唤醒延迟频率power/cpu_frequencyCPU 频率变化分析性能瓶颈Binderbinder/binder_transactionBinder 调用耗时Binderbinder/binder_transaction_receivedBinder 接收时间图形mdss/mdp_vsync_*显示 VSYNC 信号IOblock/block_rq_issueIO 请求发起内存kmem/kmalloc内存分配追踪四、atrace —— Android 用户态追踪4.1 atrace 是什么atrace是 Android 提供的命令行工具封装了 ftrace 的配置和数据采集。# 查看支持的 trace categoryadb shell atrace--list_categories# 典型输出gfx - Graphics input - Input view - View System webview - WebView wm - Window Manager am - Activity Manager sm - Sync Manager audio - Audio video - Video camera - Camera hal - Hardware Modules app - Application res - Resource Loading dalvik - Dalvik VM rs - RenderScript bionic - Bionic C Library power - Power Management pm - Package Manager sched - CPU Scheduling freq - CPU Frequency idle - CPU Idle load - CPU Load disk - Disk I/O mmc - eMMC commands...4.2 常用 atrace 命令# 基础用法追踪 10 秒抓取 sched 和 gfx 类别adb shell atrace-t10sched gfxtrace.out# 异步模式后台启动追踪adb shell atrace--async_startsched freq gfx# ... 执行测试操作 ...adb shell atrace--async_stoptrace.out# 追加 App 自定义 trace需要 App 代码中使用 Trace APIadb shell atrace-t10-acom.example.app sched gfx# 输出压缩格式减少传输大小adb shell atrace-t10-zsched gfxtrace.out五、systrace —— 可视化分析5.1 systrace 是什么systrace 是 Android SDK 提供的 Python 脚本能够调用 atrace 收集原始数据将数据转换为 HTML 可视化报告提供交互式分析界面# 使用 systrace.py位于 sdk/platform-tools/systrace/python systrace.py-t10-otrace.html sched freq gfx input view5.2 Systrace 报告解读报告分为多个 SectionCPU 调度区域每个 CPU 核心一行显示在该核心上运行的线程 CPU 0: [surfaceflinger] [app] [idle] [surfaceflinger] ... CPU 1: [Binder:1234] [idle] [app] [Binder:1234] ... 解读 - 线程名可以看出谁在占用 CPU - 颜色块表示不同的线程 - 空白 idleCPU 空闲进程/线程区域每个进程一行显示该进程各线程的状态 com.example.app (12345) └─ main (12345): [RUNNING][SLEEPING][RUNNING][BLOCKED]... └─ RenderThread (12346): [RUNNING][RUNNING]... └─ Binder_1 (12347): [RUNNING]... 线程状态颜色 - 绿色 Running - 蓝色 Runnable等待 CPU - 白色 Sleeping - 橙色 Uninterruptible SleepIO 等待 - 紫色 Blocked等待锁VSYNC 与渲染管线VSYNC: | | | | | | | SurfaceFlinger: App Render: 每个竖线表示 VSYNC 信号每个横条表示渲染操作所占的时间。理想情况下App 的渲染操作应在 16.7ms60fps内完成。Binder 调用App → Binder Transaction → System Server |---- request ----| |---- processing ----| |---- reply ----|Binder 区域显示了跨进程调用的完整时间线可以直观看出哪个方向的延迟最大。5.3 关键快捷键快捷键功能W/S放大/缩小A/D左右平移M标记当前选择的时间范围F聚焦当前选择1-4切换不同细节级别?显示所有快捷键六、API 打点在代码中埋点6.1 Java 层源码路径frameworks/base/core/java/android/os/Trace.javapublicfinalclassTrace{// ...publicstaticfinallongTRACE_TAG_APP1L12;privatestaticfinalintMAX_SECTION_NAME_LEN127;// 通过 native 方法写入 trace_markerprivatestaticnativevoidnativeTraceBegin(longtag,Stringname);privatestaticnativevoidnativeTraceEnd(longtag);// App 开发者使用的便捷 APIpublicstaticvoidbeginSection(StringsectionName){if(isTagEnabled(TRACE_TAG_APP)){if(sectionName.length()MAX_SECTION_NAME_LEN){thrownewIllegalArgumentException(sectionName is too long);}nativeTraceBegin(TRACE_TAG_APP,sectionName);}}publicstaticvoidendSection(){if(isTagEnabled(TRACE_TAG_APP)){nativeTraceEnd(TRACE_TAG_APP);}}}关键设计beginSection/endSection使用TRACE_TAG_APPtag需要 atrace 命令中加-a package参数才能采集到。MAX_SECTION_NAME_LEN限制名称最长 127 字符。使用示例importandroid.os.Trace;publicvoiddoHeavyWork(){Trace.beginSection(doHeavyWork);try{processData();Trace.beginSection(processData_sub);// 子步骤Trace.endSection();}finally{Trace.endSection();}}6.2 Native 层#includeutils/Trace.hvoiddoHeavyWork(){ATRACE_BEGIN(doHeavyWork);// 耗时操作ATRACE_END();}七、结合异常定位的实战案例案例 1UI 卡顿分析问题用户反馈 App 滑动卡顿 分析步骤 1. 抓取 systracesystrace.py -t 5 -o trace.html sched freq gfx input view 2. 打开 trace.html找到 App 的 main 线程 3. 观察 VSYNC 信号和渲染完成时间 4. 发现某个帧的渲染耗时 80ms远超 16.7ms 5. 放大该帧时间范围发现 RenderThread 在等待 CPU 6. 查看 CPU 调度区域发现同时有后台线程在密集计算 7. 结论后台任务与渲染线程抢 CPU导致掉帧 8. 修复将后台任务移到 cpuset 后台组降低优先级案例 2ANR 前兆分析问题App 偶尔 ANR但 traces.txt 中主线程没有明显阻塞 分析步骤 1. 抓取 systrace CPU 调度 2. 发现 ANR 发生前所有 CPU 核心 100% 占用 3. 主线程处于 Runnable 状态等待 CPU而非 Blocked 4. 结论系统整体 CPU 过载主线程分不到 CPU 时间片 5. 修复优化后台任务降低 CPU 使用率案例 3System Server 慢问题系统服务调用响应慢 分析步骤 1. systrace 中开启 binder 类别 2. 观察 Binder 调用链路 3. 发现 AMS 的某个方法耗时 500ms 4. 进一步查看 AMS 线程的 trace 5. 发现 AMS 在等待 PackageManager 的锁 6. 结论PackageManager 持有锁时间过长导致连锁反应八、使用技巧与最佳实践8.1 选择合适的 trace 类别# 性能分析最小集sched freq# UI 卡顿sched freq gfx input view# Binder 问题sched freq binder# 启动速度sched freq am wm# 内存问题sched freq memreclaim# 全盘分析注意数据量sched freq gfx input view wm am binder disk8.2 减小 trace 开销- 限制追踪时间-t 55 秒通常足够 - 只追踪必要的 App-a com.example.app - 使用压缩格式-z - 减少不相关的 category - 在非关键路径上减少 Trace.beginSection/endSection 调用8.3 脚本化收集#!/bin/bash# 一键收集异常现场的 trace 数据TIMESTAMP$(date%Y%m%d_%H%M%S)# 1. 抓取 atraceadb shell atrace-t10-zsched freq gfx input view binder\trace_${TIMESTAMP}.trace# 2. 导出 logcatadb logcat-dlogcat_${TIMESTAMP}.txt# 3. 导出 dmesgadb shelldmesgdmesg_${TIMESTAMP}.txt# 4. 导出 ANR tracesadb pull /data/anr/traces.txt traces_${TIMESTAMP}.txtechoAll logs collected with timestamp:${TIMESTAMP}九、总结Trace 是事前监控能力不等异常发生而是持续观察系统运行状态发现性能瓶颈。三层架构ftrace内核→ atraceAndroid 封装→ systrace可视化分析。trace_marker 是用户态与内核态的桥梁通过ATrace_begin/end或Trace.beginSection/endSection将应用级打点注入内核 trace buffer。systrace HTML 报告是核心分析工具按时间轴展示 CPU 调度、线程状态、Binder 调用、渲染管线。结合异常定位systrace 可以补充 ANR/Watchdog 分析中缺失的时间线上下文帮助判断是锁阻塞还是 CPU 竞争。下一篇将介绍 Android 日志系统全景——从 logcat 到 bugreport。注意新一代 trace 工具 perfetto 在 Android 10 中成为默认AOSP 7 以 atrace/systrace 为主。本文基于 AOSP 7Android Nougat源码编写。