Perfetto还原ANR现场：从静态堆栈到完整时间线

早上刚坐上工位测试那边就丢过来一条消息“阅读器翻页卡了几秒弹了无响应你们看看昨天就开始有了。”我第一反应是去拉 ANR 日志。/data/anr/下确实躺着几个文件堆栈也记录了但翻来翻去只看到主线程卡在一个线程等待上既看不见卡之前的输入事件是怎么积压的也看不出那把锁到底被谁占着。这就是我最近一直在强调的一个点只靠 ANR 的文本日志很多现场是还原不出来的。传统日志是案发后的“结果帧”Perfetto 能给你案发前后几秒的完整“监控录像”。标题里说的“需要 Perfetto 分析的 ANR”指的就是那种日志里只露出冰山一角、真正原因藏在时间线和跨进程交互里的 ANR。这篇文章我就用实际经验把它讲透从抓取配置、UI 分析到一次完整案例复盘再到我踩过的坑和现在固定使用的分析流程适合正在排查 ANR、但发现 traces 文件总是不够用的客户端开发。1. 为什么 ANR 必须用 Perfetto 看传统 traces 文件的三个盲区1.1 ANR 日志到底记录了啥一个结果帧当你打开/data/anr/traces或者从 bugreport 里抽出 ANR 信息时本质上是系统在 ANR 发生的那一刻对系统中所有进程做了一次堆栈快照。它主要包含三块内容发生 ANR 的进程、pid、包名以及Reason:字段能告诉我们超时类型是输入分发、广播、服务还是 ContentProviderCPU 使用率快照包括各进程在 ANR 前一段时间的负载情况所有线程的 Java 与 native 堆栈其中最核心的是主线程当时卡在哪个方法上。问题在于这个快照是“ANR 已经触发之后”的状态。系统判定输入超时并决定 dump 堆栈和主线程真正被卡住的时刻中间往往隔着几百毫秒甚至几秒。线程状态、锁的持有者信息、那些等锁的线程堆栈可能已经发生了变化。更尴尬的是很多情况下你看到主线程停在Looper.loop或某个wait上而真正占用该死锁的那把锁的线程堆栈里是打出来的但你已经拿不到它在几秒前到底执行了什么。1.2 传统方案缺失时间线Perfetto 补上全局因果链我在排查 ANR 时最想要的东西不是一张静止的堆栈照片而是一条时间线。比如下面这几个问题传统 ANR 日志几乎回答不了这个输入事件是何时进到 InputDispatcher 的主线程在此之前已经连续跑了多久的耗时任务负责持有锁的后台线程是什么时候开始执行的中间有没有被系统调度打断CPU 在那个时间段内是被我这个进程占满了还是被媒体服务、渲染进程抢走了Perfetto 能把这些全部串起来。它通过内核 ftrace 和 atrace 采集用户态、内核态的事件包括线程调度、Binder 事务、CPU 频率、锁竞争、IO 等待、图形渲染、输入分发等等。打开 trace 后你能看到过去那个“不可见”的窗口期里每个线程在干什么状态是什么颜色Binder 事务从哪个进程发向哪个进程耗时多少毫秒。原因链是连续、可见的而不是靠猜。1.3 ANR 的五种常见类型trace 分析侧重点不一样系统里最常见的 ANR 类型大概可以分成这么几类每类在 Perfetto 里看的重点完全不同ANR 类型超时时间参考Perfetto 分析侧重点Input dispatching timeout5 秒左右主线程 slice、InputDispatcher 的 waitQueue、输入事件积压时间Broadcast timeout前台/后台10 秒 / 60 秒主线程串行执行广播链、onReceive耗时、AMS 里的广播分发 sliceService timeout20 秒Service 生命周期所在进程的 CPU 状态、主线程是否阻塞ContentProvider timeout20 秒provider 所在进程的启动状态、Binder 调用publish的时延JobScheduler / 其他内部超时具体逻辑而异对应进程线程池耗尽、Binder 队列堆积标题里这种 ANR一般指的是前两类尤其是Input dispatching timeout它占了日常线上 ANR 的大头。这类问题用 Perfetto 分析最合适因为输入事件的分发链路本身就有明确的时间戳卡在哪一秒、卡了多久、主线程当时在干嘛一目了然。2. 抓一份合格的 ANR trace抓取配置与实操命令2.1 抓取前的关键决策时长、缓冲区、事件类别很多人的第一次 Perfetto 抓取是失败的主要原因不是工具不对而是参数没想清楚。抓 ANR 现场的 trace几个参数必须先定时长。推荐 15 到 30 秒。太短的话ANR 窗口期没覆盖到太长的话缓冲区被无关信息塞满关键事件反而被冲刷掉。如果问题稳定复现15 秒足够如果复现概率低就要结合 logcat 里的时间点决定宁可抓 30 秒也别抓 5 秒。缓冲区大小。默认 8MB 在抓 sched 和 binder 这种高频事件时完全不够建议配置 64MB 到 128MB。缓冲区不够的表现是抓完的 trace 前半段正常后半段出现大段空缺好像进程“消失”了其实就是 buffer covered。事件类别。核心是这几个 ftrace categorysched看线程调度和状态freq看 CPU 频率与大小核分配binder_driver和binder_lock看 Binder 方向和锁等待input看输入事件分发am、wm看系统关键事件。另外建议加上gfx和view它们能帮你看主线程有没有被帧处理长时间占用。2.2 用 adb perfetto 命令行抓取 15 秒现场在开发者选项里开启“系统跟踪”也是一种办法生成的文件格式就是 Perfetto trace。但如果要抓 ANR我还是习惯用命令行控制力度更强归档也方便。以下是实测可用的一组参数adb shell perfetto \ -o /data/local/tmp/anr_trace.perfetto-trace \ -t 15s \ -b 64mb \ -c /data/local/tmp/perfetto_anr.cfg配置文件perfetto_anr.cfg我固定这么写buffers { size_kb: 65536 fill_policy: RING_BUFFER } data_sources { config { name: linux.ftrace ftrace_config { ftrace_events: sched/sched_switch ftrace_events: sched/sched_wakeup ftrace_events: sched/sched_waking ftrace_events: power/cpu_frequency ftrace_events: binder/binder_transaction ftrace_events: binder/binder_transaction_received ftrace_events: binder/binder_transaction_alloc_buf ftrace_events: binder/binder_transaction_lock_acquire ftrace_events: binder/binder_transaction_lock_release ftrace_events: print/print atrace_categories: am atrace_categories: wm atrace_categories: input atrace_categories: view atrace_categories: gfx } } }抓取时比较实用的一个做法是在点击“开始复现”之前先在命令行里加一条 logcat 标记adb logcat -c adb logcat -v threadtime /tmp/logcat_anr.log adb shell perfetto ... # 然后立刻去复现操作这样 trace 和 logcat 的时间线能对起来后面用am_anr事件反查 ANR 时刻非常方便。2.3 从 bugreport 中抢救过期 trace 的兜底方案如果 ANR 已经发生过、没有现场抓到 Perfetto trace也不是完全没救。可以看看adb bugreport拉下来的压缩包里有没有dumpsys开头的文件、/data/anr/目录甚至traces_01之类的堆栈。但要注意这些是静态快照时间维度是缺失的。还有一条路径是看系统是否保留了traces_proto或者perfetto抓取的历史内容。部分系统在 ANR 时会自动落一份 nativetrace格式不一定是.perfetto-trace但可以通过trace_processor转换后丢进 Perfetto UI。这个功能各 ROM 差异很大不保证一定有效。所以我的原则是能现场复现的必须先原地抓 trace再谈分析。3. 在 Perfetto UI 里还原 ANR 案发过程从时间点到根因3.1 第一步锁定进程和时间窗口打开ui.perfetto.dev之后先把刚才的 logcat 拿出来找到这条ActivityManager: ANR in com.someapp.package ActivityManager: Reason: Input dispatching timed out ...记住那个时间比如16:22:33.400。然后在 Perfetto UI 左上角的搜索框里搜am_anr可以直接定位到系统事件的确切位置。这一步非常重要别直接凭“感觉”去滚动时间轴误差会很大。接着在搜索框里输入你的包名或进程名UI 会列出相关的进程和线程 track。找到主线程 trackANR 的所有分析都从这里开始。先做时间窗口聚焦把视图居中到am_anr事件前 5 秒到事件后 2 秒后面的步骤全部在这个窗口里做。3.2 第二步判断主线程是“忙”还是“等”这是整个分析里最关键的一步。看到主线程 track 下面花花绿绿的块先别急着看某个 slice 的函数名。要先判断ANR 窗口内主线程的状态是什么颜色线程状态Perfetto 中的表现含义Running蓝色实心正在 CPU 上执行代码Runnable绿色想跑但没拿到 CPU在等待调度Uninterruptible Sleep橙色Deep内核态不可中断等待常见于磁盘 IO、Binder 某些场景Sleep灰色主动休眠比如等锁、wait如果主线程长时间 Running说明它一直有事在忙问题很可能出在业务代码本身某个任务太重或者onTouchEvent里做了什么同步操作。这时候要看的是占用时间最长的那个 slice把它展开一路往下钻。如果主线程大部分时间是绿色 Runnable说明它没有 CPU 配额。这时候要去看同一时间点上其他进程里有哪些线程在大规模占据 CPU。我遇到过好几次主线程在绿着等而真正的元凶是一个疯狂跑在后台的渲染合成进程。如果主线程是橙色不可中断等待就得往内核态看通常与存储 IO、page fault 有关。这种情况 ANR 日志里经常表现为主线程堆栈停在file_read或__futex附近。3.3 第三步沿 Binder、锁和调度链路找元凶一旦确认主线程在等待就顺着“等待的对象”往下查。最常见的是 Binder 调用等待。在 Perfetto 里搜索binder/binder_transaction类别的事件能看到主线程在哪个时刻发起了一个 Binder call到哪个进程对方跑了多久才回复。这把锁常常藏在后台线程里。这时候要做的是搜索所有binder_transaction_lock_acquire和binder_transaction_lock_release事件找到与主线程等待时间重合的那一段再看持锁的是哪个线程它的堆栈是什么。搜索范围不要只限制在自己进程系统服务进程比如 system_server也可能持有你正在等的锁。一个实用技巧是直接在 UI 里选中主线程那一段等待区间然后在右侧Selected slice面板里看关联的sched/sched_switch它会告诉你切换出去的下一把 CPU 被谁拿走了、拿走了多久。3.4 用 SQL 快速过滤疑点进程缩小排查范围Perfetto 自带 trace_processorUI 界面右下角有个 “Query” 页面可以直接写 SQL。我用得最多的一条查询是select process.name as proc_name, thread.name as thread_name, sum(dur) / 1e6 as total_millis from thread_state join thread using (utid) join process using (upid) where thread_state.state Running and ts between ANR开始时间 and ANR结束时间 group by process.name, thread.name order by total_millis desc limit 20;这条 SQL 能快速告诉我ANR 那段时间里整个系统到底是谁在疯狂消耗 CPU。如果排在前面的是你自己的后台线程、媒体线程或者其他系统服务接下来分析的主线立刻清晰很多。另外还可以查select * from slice where name like %methodName% and ts between ...直接定位到某段可疑函数在所有进程里的执行时间分布比在手机屏幕上慢慢滚动快得多。4. 一次输入分发超时的完整复盘主线程在等一把锁4.1 案例现状翻页卡顿并弹出无响应前面提到的某阅读类 App线上反馈集中在“连续翻页后点击书架无响应”。抓到 ANR 日志Reason是Input dispatching timed outWaitQueue里积压了两个事件。比较典型的现象这个 App 的阅读页在翻页时会触发一系列图片解码、缓存淘汰操作后台有一个图片预处理线程池不断把新读入的图片转成 RGB 位图放进内存缓存。初步怀疑是主线程被耗时的图片处理拖住了于是我用抓好的 trace 打开分析。4.2 trace 中的证据链把时间轴线定位到am_anr事件前 3 秒看到主线程 track 的表现是这样的主线程先是正常处理了一次触摸事件耗时大约 80ms紧接着主线程 slice 里出现了一个syncExec类型的块名字是内部图片库里的BitmapCache.getSync直接横跨了 2.9 秒这 2.9 秒期间主线程状态大部分时间是绿色 Runnable中间零星有几段蓝色与此同时图片解码线程池里有一个 worker 线程正处于 Running执行的是BitmapRegionDecoder.decodeRegion在 2.9 秒里几乎没停过。顺着这条线查 Binder 和锁事件发现主线程的BitmapCache.getSync等待的是一把名为mTrimMemoryLock的锁而持锁时间最长的正是那个在高强度执行decodeRegion的后台线程。整个逻辑链就闭环了后台图片预处理线程拿到mTrimMemoryLock开始批量解码大图主线程在翻页的某个逻辑点上以同步方式请求同一张缓存位图尝试获取mTrimMemoryLock后台线程因为连续解码大图占用 CPU 和锁的时间远超过了输入分发的超时阈值触摸事件无法被主线程及时处理InputDispatcher判定 5 秒无响应触发 ANR。4.3 修复思路与实际结果修复方案没有直接粗暴地“保证锁不冲突”而是做了三件事主线程不再同步等待锁getSync改为先返回占位图缓存加载完成后在主线程抛回调拆分锁粒度把整进程的一把缓存大锁拆成按缓存条目分片的锁限制后台解码并发的位图尺寸避免解码线程把 CPU 完全占满给主线程和 UI 刷新留出调度余量。改造之后同一台测试机上连续执行之前必现的“翻页后点击书架”流程WaitQueue积压事件消失24 小时压测没有复现 ANR。相比之前只能从堆栈猜测“主线程在等锁”Perfetto trace 让我们能准确说出“等的是哪把锁、被谁占着、占了多少毫秒”定位误差小了一个数量级。5. 我踩过的坑和现在的固定分析流程5.1 四个让 trace 废掉的低级错误先说坑这些坑我有过真实教训浪费过不少时间。第一个坑是缓冲区太小。开始我用默认 8MB 抓 30 秒等打开 trace 才发现后半段一片空白。后来固定 64MB 以上顺手把输出文件也改了名就再没遇到过。第二个坑是没录 logcat 时间点。只抓了 trace但不知道 ANR 在 trace 里的确切位置。只能在 UI 里靠肉眼找输入事件堆积的位置效率极低。现在我每一次抓 trace 之前都会先adb logcat -c抓完就立刻拿am_anr关键词对齐时间线。第三个坑是事件类别太少。我早期只抓了 sched 和 freq结果某个 ANR 里 Binder 墙上时间非常长但完全没有 binder 事件无法确认到底是不是 Binder 等待导致的。后来把binder_driver和binder_lock常驻配置后这类问题基本遇不到盲区。第四个坑是只盯主线程忽略全局。有一回的 ANR主线程切片显示它在等一次网络结果的回调但真正的问题是一场GC引发的全局停顿和外部进程 CPU 抢占。如果不看全局调度只看主线程会得出“网络库延时导致 ANR”这种错误结论。5.2 三分钟逆推法我的 ANR trace 排查套路现在每次拿到一个新的 ANR trace我的固定流程是这样基本三分钟内能判断大致方向对齐时间搜索am_anr或从 logcat 拿到精确时间点看主线程颜色分布根据蓝、绿、橙的占比判断是业务耗时、调度饥饿还是内核等待看输入 waitQueue搜索InputDispatcher确认事件从触碰到处理间隔了多久用 SQL 找热点查询 ANR 窗口内进程/线程的 Running 时长排名顺着锁和 Binder 链反向锁定真凶拿到持有资源者的线程名和堆栈。这套流程适用于大多数输入分发超时和主线程阻塞型 ANR。如果问题卡在第五步还找不到我会再加一步对比分析 ANR 窗口前、中、后三个时间片的线程状态差异。很多时候主线程在 ANR 窗口前已经出现过一次短暂卡顿而那一次的持锁线程早就结束了执行只有通过 slice 切片对比才能看清。5.3 必要的兜底工具与可复用的配置模板最后说下我日常保留的兜底方案。除了命令行抓取还可以在开发者选项里预先开启“系统跟踪”快捷开关真机出现偶现 ANR 时下拉栏就可以快速抓不用再连电脑。如果需要后台持续监控可以用 Perfetto 的--background模式配合时间窗口写入文件。我上面给的perfetto_anr.cfg配置基本可以直接复用。如果机型比较老有些 ftrace 事件可能不存在抓取时会有告警不影响其他事件采集。打开 trace 时建议用最新版 Perfetto UI老版本对部分binder_lock事件和thread_state的可视化支持不全。根据我自己的切身体会ANR 排查最大的转折点就是从“看静态堆栈”过渡到“看完整时间线”。Perfetto 需要一点点学习成本但投入产出比很高。第一次完整还原出主线程等待锁被哪个线程持有的时候你会明显感觉到之前那种靠猜去优化代码的日子算是彻底过去了。如果你手头正好有个百思不得其解的 ANR别犹豫照着上面的配置抓一份 trace多半第一轮分析就能给你足够的方向。