做了两年Android业务开发最头疼的问题之一就是线上用户反馈“App卡成PPT”本地复现却怎么都回放不了。开发阶段还能连上Perfetto看trace可线上几十万用户手里每个机型、每个系统版本、每个应用状态都不一样那种只在用户手机上出现的卡顿几乎只能靠猜。被现实毒打过几次之后我决定给线上加一套卡顿检测探针方案选来选去最后落了地“基于Handler机制”的轻量实现。这套方案在业界已经属于“标准动作”原理不复杂接入成本低能覆盖大部分主线程耗时问题很适合做APM系统里的第一层卡顿监控。这篇文章我会从选型思路讲起把Looper、Printer、dispatchMessage这一串底层机制拆开然后给出完整的线上探针实现、卡顿现场采集方案以及我在真机环境和线上数据里踩过的一堆坑。如果你正在做性能监控或者想给App加一个通用卡顿上报工具这篇文章可以直接参考。1. 方案选型为什么卡顿检测要从Handler机制下手1.1 用户感知的卡顿本质是主线程“堵车”在Android里UI的每一帧绘制、每一次触摸事件、每一条生命周期回调最终都会被封装成Message放到主线程的MessageQueue里由Looper.loop()不断从队列里取出来执行。主线程只有一个所以一旦某条Message的处理时间超出了预期后面的消息就只能排队等着屏幕就在原地停住用户看到的就是“掉帧”“卡死”“响应慢”。所以卡顿检测的第一原则就是盯住主线程的消息执行耗时。只要一条消息的执行时间超过了合理阈值就说明这段路上出现了“堵车点”而这个堵车点往往就是某个方法里的耗时操作同步网络请求、大文件IO、复杂的布局计算、主线程上的锁竞争、不合理的Binder调用等等。顺着这个思路最直接的检测位置就是消息分发的前后。Android的Looper在设计时就留了一个探针接口Looper.setMessageLogging(Printer)它在每一条消息dispatch之前和之后都会回调Printer.println()。我们只需要实现一个自定义Printer计算这两次回调之间的时间差就能准确测量“单条消息的执行耗时”。这个方案不侵入业务代码不需要改造Handler也不需要业务方配合埋点是典型的无侵入探针。1.2 现有检测手段的局限性对比做线上卡顿检测主流路线其实有这么几条方案实现方式优点局限Perfetto/Systrace系统trace抓取能看到整条渲染链路、线程调度、CPU频率需要开发者授权或root无法规模化线上采集Choreographer.FrameCallback注册帧回调计算相邻两帧间隔直接反映掉帧次数数据直观只能知道“掉帧了”无法定位是哪个消息或哪段代码导致的UI线程埋点在业务关键方法里手动记录时间定位准确需要业务方配合覆盖不全后期维护成本极高Handler消息时长检测自定义Printer监听dispatch前后自动覆盖所有主线程消息能定位到具体消息与耗时只能检测消息执行本身检测不到渲染管线、线程调度等外部因素当时我对比下来Choreographer方案适合做“掉帧率大盘”但它给不了“卡在哪个函数”的线索Perfetto又太重线上没法铺。反而是Handler方案虽然看待问题的角度有点“朴素”但胜在范围全覆盖、自动探针、定位到消息级别。作为线上第一道卡顿粗筛它最合适。1.3 Looper天然适合做卡顿探针的原因这里有一个关键认知Looper.loop()的执行其实是串行的。主线程Looper在queue.next()取出消息之后会执行final Printer logging me.mLogging; if (logging ! null) { logging.println( Dispatching to msg.target msg.callback : msg.what); } msg.target.dispatchMessage(msg); if (logging ! null) { logging.println( Finished to msg.target msg.callback); }源码里的mLogging就是通过setMessageLogging注入的Printer。这两行日志的打印时机正好把dispatchMessage的执行过程包在中间。也就是说只要我们在Printer的println里记录下 Dispatch和 Finished两行日志出现时的系统时间差值就是这条消息的实际执行耗时。这个设计本身是Android为了给调试工具提供信息留下的“官方后门”我们不搞黑科技只是把这个机制用在线上监控里。另外这套方案还有一个隐藏优势它检测的是“主线程真正在处理每个消息时的耗时”不会把等待空闲的时间算进去。用户不会因为主线程在等下一个vsync而觉得卡只有“有消息要处理但处理不过来”才是真卡顿。Printer的位置恰好只覆盖到消息处理阶段目标非常精准。2. 核心原理拆解Printer的打印时机与耗时计算2.1 先看清Looper打印日志的完整时机上面那段源码很多时候大家看一眼就过了但实际上里面藏着很多工程细节。我在实现时反复读了几个Android版本的Looper源码发现要注意这么几点第一logging.println( Dispatching...)和logging.println( Finished...)之间只有一次dispatchMessage调用。也就是说如果这条消息内部又通过handler.post()发了一条新消息新消息不会立即执行它要等当前消息跑完、回到loop()循环时才会被处理。所以Printer测出来的是“当前消息完整的同步执行时间”任何阻塞在这个方法里的代码都会计算在内。这正好符合我们的需求。第二msg.target.dispatchMessage(msg)里可能执行的逻辑包括Handler的handleMessage、Runnable的run()以及系统内置的某些Callback比如ViewRootImpl里的TraversalRunnable。所以Choreographer的帧回调、输入事件分发、View绘制流程本质上都是通过Handler消息在主线程执行的。换句话说我们的探针能覆盖到绝大多数主线程耗时场景包括布局和绘制的部分阶段。第三queue.next()阶段是不会打印日志的。这个阶段可能是消息队列为空时的等待也可能是在等下一个任务被唤醒还有可能是同步屏障导致某些消息被延迟分发。这一部分造成的“延迟”Printer是看不到的。这会在后文讲到“方案盲区”时详细展开先有个印象。2.2 利用时间差计算消息耗时墙钟时间与CPU时间实现Printer的核心逻辑其实非常简单但要把时间算准需要区分两种时钟墙钟时间Wall TimeSystemClock.elapsedRealtime()表示从系统启动到现在经过的真实时间包括休眠时间。它适合用来衡量用户感知到的延迟。CPU时间Thread TimeSystemClock.currentThreadTimeMillis()表示当前线程实际运行消耗的CPU时间不包括等待和休眠的时间。为什么两套时间都要因为实践中会遇到两种情况一种是消息执行中确实在做大量运算或IOCPU时间接近墙钟时间另一种是消息执行时遇到了Binder调用或锁等待主线程被block住但CPU时间很短。比如主线程调用了一个系统服务系统服务迟迟不返回这时候主线程其实是在binder线程里等回复墙钟时间已经过去300ms但主线程自己的CPU时间可能只有几毫秒。在线上做归因时这个区分非常有用。如果判断出“墙钟时间大、CPU时间小”那大概率是等待外部资源可能是Binder调用、文件锁、跨进程IPC如果“墙钟时间和CPU时间接近”那基本就是主线程在疯狂做计算或者GC压力大属于纯粹的“主线程过载”。我们上报数据时把这两个时间带上去后续分析就能自动给卡顿打上“等待型”或“计算型”的标签不用人工猜。public class LooperMonitor implements Printer { private long dispatchStartWallTime; private long dispatchStartThreadTime; private boolean inDispatch; Override public void println(String x) { if (x null) { return; } if (x.startsWith( Dispatching)) { dispatchStartWallTime SystemClock.elapsedRealtime(); dispatchStartThreadTime SystemClock.currentThreadTimeMillis(); inDispatch true; } else if (x.startsWith( Finished)) { if (!inDispatch) { return; } long wallCost SystemClock.elapsedRealtime() - dispatchStartWallTime; long threadCost SystemClock.currentThreadTimeMillis() - dispatchStartThreadTime; checkBlock(wallCost, threadCost, x); inDispatch false; } } }这里有一个容易被忽略的细节如果消息执行过程中发生异常或者被系统强制调度可能出现只有没有的情况。所以代码里必须要有inDispatch这个状态位避免后续消息的Finished日志错误地算到前一条消息头上。在长期运行中这个状态位能避免很多脏数据。2.3 阈值设置与误报规避阈值怎么定决定了一轮监控是“过敏”还是“漏报”。我做线上监控时不会用一个固定值而是把卡顿分了两档轻微卡顿消息执行超过100ms。这个阈值基本对应一次明显可感知的UI停顿录屏回放里能看到轻微掉帧。严重卡顿消息执行超过500ms。这个阈值基本意味着用户已经能明显感觉到“卡死”或“应用无响应”也是ANR的候选前兆。但直接套阈值有个问题低端机和中端机对时间的敏感度不同一台百元机和一部旗舰机跑同一条耗时逻辑耗时差个两三倍很正常。所以更合理的方式是“按设备档位配置阈值”通过采集设备CPU核心数、内存大小、运行时长把设备分几个档位或者先自适应跑两周统计每个消息耗时的P85、P95再动态调整阈值。还有更细的做法是把阈值下发到配置中心线上按版本、按灰度通道调整这样能在不同机型池子里做到差异化。另外还要注意“单条消息耗时”并不等于“单帧耗时”。有时候两条消息都只用了50ms但它们中间隔了很久用户照样觉得卡。Handler探针只会把每条50ms的消息标记为不卡这就漏掉了因为“消息排队”引起的掉帧。要解决这个问题通常需要结合Choreographer的FrameCallback统计掉帧率再和Handler探针的数据做联动。这也是我在后面章节会讲到的“组合拳”。3. 线上方案的落地实现低侵入探针怎么做3.1 初始化LooperMonitor的正确姿势在Application里初始化时直接用Looper.getMainLooper().setMessageLogging(monitor)在大多数版本上是行的但为了稳妥我建议统一走反射。为什么因为Android版本分裂严重部分高版本系统对非SDK接口有限制而那些厂商改过的ROM更是无法预测。先用反射尝试调用反射失败就放弃初始化不要因为这个探针导致App崩溃。初始化代码可以这样写public static void install() { if (installed) { return; } try { Looper mainLooper Looper.getMainLooper(); Method setMessageLogging Looper.class.getMethod(setMessageLogging, Printer.class); setMessageLogging.invoke(mainLooper, new LooperMonitor()); installed true; Log.i(PerfMonitor, LooperMonitor installed); } catch (Throwable t) { Log.e(PerfMonitor, install failed, t); } }这里注意两点一是反射结果一定要用installed标记避免重复设置。二是如果系统里其他模块也设置了MessageLogging比如某些调试SDK我们要把旧的Printer保存下来在自己处理完逻辑后再转发给旧Printer。否则我们可能把别人Debug用的日志输出给吞了或者被别人覆盖。3.2 卡顿现场采样不能等消息结束才抓堆栈上线的卡顿检测最核心的诉求不只是“知道多久”更是“知道卡在哪儿”。但很多第一次实现的人会在这里栽跟头消息执行完、在onDispatchEnd里判定超时后再去抓主线程堆栈很可能已经晚了。因为此时那条耗时的消息已经执行完毕主线程可能已经跑到下一条消息上去了你抓到的堆栈和真正卡顿时的堆栈完全对不上。正确的做法是“提前布防持续采样”。具体来说在println收到 Dispatch时把当前消息的开始时间记录到公共变量里并打开一个“采样开关”。启动一个轻量的采样线程比如HandlerThread每隔50ms检查一次如果当前仍在dispatch中并且已经超过预设的“预触发阈值”比如50ms就立即抓取主线程的Current Thread StackTrace并记录当时的墙钟时间、CPU时间。直到收到 Finished时关闭采样开关。这时我们拿到的是一串“卡顿期间按时间排序的堆栈序列”最后再根据实际总耗时决定是否上报。这种“时间切片采样”的好处是即使一条消息卡了1秒我们也能看到主线程在这1秒里的代码路径变化。比如刚开始可能阻塞在IO读文件后面又跑到Gson解析流程一目了然。堆栈采集本身也需要注意性能。从子线程调用mMainThread.getStackTrace()不会阻塞主线程但如果采样太频繁比如10ms一次会把CPU打高反而制造卡顿。我实践下来卡顿期间50ms采一次足够不会产生明显负担。线上只对“疑似卡顿”开启采样平时不做任何额外动作。主线程堆栈抓取示例public void sampleStackTrace(Thread mainThread, long wallTime) { StackTraceElement[] stack mainThread.getStackTrace(); // 压缩堆栈信息去掉无用的系统帧截取前30层 // 记录到本地buffer等待消息结束后统一组装 BlockRecordHolder.addSample(wallTime, stack); }3.3 上报数据要带哪些字段一个可用的线上卡顿数据包至少包含这几个维度数据项说明发生时间精确到毫秒用于和线上崩溃、网络慢请求进行时空碰撞墙钟耗时用户感知的卡顿时长线程CPU耗时区分计算型/等待型卡顿消息内容target的类名、callback、what用于初步定位是哪个Handler堆栈采样序列卡顿期间的多次主线程堆栈按时间排列系统状态进程CPU占用、设备型号、系统版本、前后台状态、可用内存应用状态当前Activity/页面路径、冷启动还是热启动、是否处于动画中不用一次全采因为采样本身有代价。我的习惯是先把堆栈序列和耗时写进内存环形缓冲区当判定为严重卡顿时才完整组装并异步上报轻微卡顿只上报聚合信息次数、耗时分位数、Top堆栈不逐条上报否则数据量会爆炸。3.4 上报策略与节流线上网络不可控特别是卡顿发生时应用本身可能已经很卡了再做同步网络请求只会雪上加霜。所以上报一定要异步、批量、可丢弃用独立的HandlerThread负责数据组装和网络写入。先写到本地文件App进入后台或等到网络空闲时再批量上报。同一进程内连续上报需要节流比如2分钟内最多上报10条超过的合并成一条“聚合卡顿”记录。如果发生非常频繁的连续卡顿比如500ms超时出现了几十次可能是应用已经处于极端异常状态这时候要保护性地暂停采集避免把系统拖垮。这里还有一个容易被忽略的点卡顿上报本身也可能产生内存分配分配又会导致卡顿形成恶性循环。所以探针内部要减少对象分配比如格式化日志尽量复用StringBuilder堆栈压缩时避免使用正则等等。3.5 混淆与兼容性问题线上App通常开了混淆。反射调用setMessageLogging走的是字符串方法名混淆不影响但采集到的堆栈是混淆后的类名和方法名如果不做映射数据基本没法看。有两类解决办法留存各个发布版本的mapping.txt在上报平台做反混淆还原。或者在上报时就上传混淆后的类名服务端用最近一次构建的mapping进行映射。同时由于android.os.Handler、android.os.Looper这些系统类在部分ROM上可能会被厂商改造实际表现可能和AOSP源码有差异。不要假设所有设备都会稳定打印 Dispatching开头判断时最好同时兼容几种前缀方式比如用contains(Dispatching)而不是startsWith。4. 数据有效性分析Handler探针能检测到什么漏掉了什么4.1 这套探针能抓到的典型问题在我实际接过的项目里通过这套探针找到的主要问题有这几类第一类是主线程中的同步IO。最常见的是把数据库查询、SharedPreferences写入、文件加载直接放在主线程。这类问题的特征非常明显CPU时间偏高堆栈里能看到execSQL或者FileInputStream.readBytes。第二类是锁等待和Binder等待。比如通过主线程去获取ContentResolver的某个cursor实际上会走跨进程Binder等待远端服务返回或者两个线程抢占某个锁主线程长时间拿不到锁。这类卡顿通常是墙钟时间远大于CPU时间堆栈里能看到IPCThreadState::waitForResponse这样的帧。第三类是布局和绘制超时。因为ViewRootImpl的performTraversals流程是通过Choreographer投递到主线程Handler里的所以一次复杂的页面加载导致measure/layout耗时过长也会被探针捕获。这也是Handler方案可以兼做“布局卡顿发现”的原因。第四类是GC压力。频繁创建对象导致主线程触发GC卡顿的堆栈上会看到很多分配点结合CPU时间和堆栈中的art::gc相关帧可以判断出GC卡顿。4.2 这套探针漏掉的问题使用这个方案必须清楚它测的是“主线程单条消息的执行耗时”不是“整帧耗时”。所以下面这些问题它是测不到的帧调度延迟如果主线程当前没有消息在执行但队列里的下一个帧回调因为同步屏障被延迟了Printer不会打印任何内容也就检测不到这段延迟。实际上这种情况在“主线程空闲但下一帧迟迟不来”时确实会出现掉帧但它不属于“某个消息执行慢”而是属于“消息没有被及时分发”。IdleHandler耗时主线程在消息队列空闲时可能执行IdleHandler比如延迟加载、预加载任务。IdleHandler的执行发生在queue.next()内部不在消息分发的dispatchMessage前后所以同样不会被Printer捕获。如果某个IdleHandler里做了一个300ms的操作用户在这期间点击屏幕会明显感到点击响应慢但探针可能毫无反应。渲染管线耗时如果掉帧的瓶颈在渲染线程、GPU或SurfaceFlinger主线程消息执行很快Handler探针只能看到“明明executed很快但用户觉得卡”。这种情况需要接入doFrame回调或其他帧率统计才能发现。所以我在实际设计监控体系时会把Handler方案定位成“主线程消息耗时监控”再配一个Choreographer.FrameCallback的掉帧统计两者互相补充FrameCallback负责记录有没有掉帧Handler负责记录为什么会卡在某个消息上。这也是业界很多成熟APM的标准搭配。5. 工程实践中的常见问题与排查实录5.1 设备兼容性setMessageLogging被覆盖或失效我遇到过一种情况在部分定制ROM上系统的某些模块会自己调用setMessageLogging覆盖掉我们设置的Printer还有的系统ROM把Looper的loop()方法改动过导致mLogging虽然存在但不打印日志。排查方法是打一个测试包在Log里观察是否出现 Dispatching输出。如果没有就是设置没生效。解决方案分两步第一步保存旧的Printer并在自定义Printer的println中转发给旧Printer保证旧功能不受影响第二步定期检查当前mLogging引用是否还是我们设置的那个对象。如果不是说明被覆盖了重新设置一次。这里要注意检查mLogging字段也需要反射并且要处理并发问题建议放在子线程做频率不要太高一小时一次即可。5.2 大卡顿产生异常多的卡顿记录有一次线上反馈某个版本的卡顿上报数量突增了几十倍。去后台一看原来是一个网络库的一个bug导致主线程在大面积等待DNS解析每次等待都在400ms左右而且是一条消息完成后紧接着下一条消息又卡短时间内产生了上百条卡顿记录。上报系统被刷爆也干扰了正常卡顿top列表。后来我加了两个机制解决同一次卡顿窗口合并如果两条超时消息之间的间隔小于500ms就把它们合并为一次“长卡顿事件”只上报一次但附带多个消息的记录。单日上报上限单个设备、单天最多上报50条卡顿超过后进入到只统计不采集堆栈的低频模式。这样既能保证数据量可控又不至于完全丢失监控。5.3 抓“慢消息”的内部堆栈为什么抓不到关键帧初版实现里我在onDispatchEnd发现超时才去抓主线程堆栈结果线上的堆栈基本都是MessageQueue.next或者Looper.loop完全没体现出真正的耗时函数。原因是消息已经执行完了主线程已经回到空闲等待或者下一条消息了。改成“卡顿期间持续采样”之后才正常。具体做法我在3.2节里写了消息一开始就打开采样线程每隔几十毫秒抓一次。这里再补一个细节如果卡顿发生在极短的时间窗口比如100ms采样线程可能还没来得及触发就结束了。这种情况可以依赖“结束后的补充采样”通过尝试启动一次立即采样来获取主线程当前堆栈虽然可能已经偏离但有时仍然能抓到同一条消息的执行痕迹因为有部分耗时逻辑可能是异步回调带来的。5.4 如何设置阈值才不会误报或漏报阈值设置既有数据问题也有体验问题。固定100ms在低端机上可能每天上报几十条让业务方觉得“线上怎么这么多卡顿”在高端机上又可能漏掉真实的轻微卡顿。我的最终实践是“分档动态”先按机型CPU性能跑分分成高、中、低三档。低档机轻微卡顿阈值调成150ms高档机调成80ms。再用一段时间的真实数据做校准取这个档位P90耗时为“关注阈值”P99为“严重阈值”。还有一个经验如果某个页面本身布局复杂首帧耗时较长这在用户体验上可能是“启动慢”而不是“卡顿”可以用“是否在前台可见”“是否在启动阶段”“是否有动画进行中”这些上下文再过滤一层避免把首屏加载时间误报成卡顿。5.5 隐私与合规注意事项卡顿数据里最容易触碰隐私的就是消息内容和堆栈内容。消息对象可能包含Intent的data、Bundle里的敏感数据打印msg.target时可能会调用Handler的toString把Activity名、回调对象的内容打印出来。线上收集时一定要在端侧做脱敏不打印消息对象本体只截取类名堆栈行号保留但涉及用户数据的字段一律不上报。同时要在隐私政策里明确说明收集性能数据不能偷偷采集用户页面信息和参数。6. 后续演进Handler探针可以与哪些方案协同工作6.1 结合掉帧率统计建立“卡顿主线程掉帧副线程”双视图前文提到Handler探针拿不到真正的帧率所以我会同时用一个Choreographer.FrameCallback做掉帧统计。每次doFrame时记录上一帧的时间戳如果间隔超过16.6ms就计一次掉帧再按间隔大小分档轻微掉帧、严重掉帧。但要注意在API 24以下Choreographer.FrameCallback也是可以用的只是某些ROM上回调时机有偏差需要兼容。拿到掉帧数据后可以和Handler探针的卡顿事件做时间关联如果一次掉帧发生的时间窗口内存在一条超时的Handler消息那基本可以确认为“主线程消息耗时导致掉帧”如果掉帧窗口内主线程消息都很快那就要去查渲染线程和GPU了。这个“三阶段联动分析”比只看任何单一指标都更接近真相。6.2 引入Trace机制定位热点函数Handler探针只能告诉我们“哪个消息耗时”但如果消息内部是几百行的复杂逻辑仅靠堆栈采样可能不够。堆栈采样本质是“抽样”如果某个热点函数不是全程占用采样可能漏掉。想要精确到方法级可以考虑在卡顿发生时开启一段轻量Trace比如使用Debug.startMethodTracingSampling但线上开启MethodTracing的性能损耗很大我一般只在“严重卡顿”且设备性能充足的场景下按概率开启并且限制最多采集几百毫秒。这样能拿到方法级别的热点数据但要注意上报文件体积。6.3 卡顿数据的聚合与排序线上卡顿数据收集上来后不能只看单条要做归一化聚合。常见的做法是把卡顿堆栈里“调用顺序的前N层”作为签名相同签名的卡顿归成一类再统计这类卡顿的影响用户数、次数PV、占比和平均耗时。通过这个“卡顿Top榜”才能指导优先级。如果没有这一步线上数据一堆乱麻根本无法决策。聚合时要注意堆栈指纹的稳定性。混淆版本变化会导致类名变化所以签名不能用完整的混淆堆栈最好只取“前3层”加上“所归属的页面路径”再结合代码版本号做分桶。某版本更新后某个旧签名消失了说明问题被修复了这也是一轮监控闭环成功与否的判据。6.4 从卡顿检测走向ANR预判Handler探针的长时间卡顿往往是ANR的前奏。如果一条消息执行超过5秒在线上很多是Binder等待、主线程被suspend大概率会触发ANR弹窗。利用这一点可以把“超过3秒的消息执行”单独标记为“ANR风险事件”并在此刻优先采集比卡顿更完整的信息主线程堆栈、其他关键线程堆栈、CPU占用率、每一次GC日志等。这样即使系统的ANR弹窗因为各种原因没有生成trace文件我们也能在端侧拿到一份近似的“准ANR现场”。我在这套实现里还会主动观察ANR之后的进程状态因为有些ANR发生在后台用户并没有直接看到弹窗但系统会杀掉进程。接入了线程池和后台任务的监控后能把这些“后台ANR”也抓出来修复了一批因为JobScheduler任务和ContentProvider初始化导致的稳定性问题。6.5 我对这套方案的最终体会接入了Handler探针之后我最直观的感受是“原来线上卡顿比我想象的多而且大部分都能从主线程堆栈找到原因。”以前只能让用户反馈、让测试复现的日子现在至少有了第一手的自动化数据。但它绝对不是万能药它只能帮你盯住“主线程消息执行”这一个维度那些发生在渲染管线、系统服务、CPU调度层面的问题还需要其他工具配合。如果你打算自研APM或者只做一个轻量卡顿监控模块我的建议是先从Handler方案起步因为它代码量最小、接入成本最低、收益立竿见影。先把“主线程消息耗时”这个基本功做好再把掉帧统计、堆栈采样、聚合上报一层层加进去最后自然形成一套适合自己业务形态的卡顿监控体系。方案不复杂真正的复杂度在工程落地和数据归因上这也是性能优化最有价值的部分。