Spring StopWatch实现接口分段计时与慢请求定位实践

1. 为什么我最终把计时工具锁定在 StopWatch 上线上接口偶尔抽风运维群里甩来一张监控截图说“这个接口白天有几次特别慢”然后所有人开始猜是数据库慢是某个远程调用抖动还是业务代码里哪段循环写得有问题这种场景我经历过太多次早期我的做法是在方法头尾各打一行System.currentTimeMillis()日志里两行时间戳一减看着挺直观。可用不了多久就乱套——一个方法里嵌了三段逻辑想分别知道各自的耗时就得定义一堆long start1、start2、start3嵌套调用一多变量名都编不出来最后还要手工算毫秒差、手工拼日志字符串一旦中途抛异常结束时间那行压根打不出来耗时统计直接断档。后来我把这套土办法换成了org.springframework.util.StopWatch。它属于 Spring 核心工具包一个类、零额外依赖只要项目里引了 spring-core 就能用。核心能力说白了就三件事给多个任务分别计时、汇总总耗时并算出各任务占比、以人类可读的格式一次性输出。它解决的不是“性能分析”这种大命题那是 arthas、async-profiler 的活而是在业务代码内部做轻量级分段计时让你在日志里一眼看出“这个方法总共花了 800ms其中查库 620ms、组装 150ms、其他 30ms”。适合谁看如果你正在做接口性能优化、需要给慢请求加埋点、或者单纯想在日志里留下可追溯的耗时明细这篇内容对你直接有用。即便你之前完全没用过这个类跟着下面的步骤走一遍半小时内就能把它接进现有项目。需要说明的是文中涉及的工程结构、日志样例、参数阈值均来自我日常的实践整理部分细节属于基于常见工程惯例的合理补全你在自己项目里落地时需要按实际情况调整。2. 先把 StopWatch 的脾气摸清楚2.1 它到底能干什么不能干什么很多人第一次看到StopWatch会误以为它是个性能剖析器这是最大的误解。我先把边界划清楚避免你用错地方然后回来骂它不好用。能力项是否支持说明单次计时start/stop支持最基本的用法一次任务一段耗时多任务分段计时支持一个 StopWatch 里可以开多个 task各自独立任务耗时占比统计支持prettyPrint()自动算百分比嵌套计时父子结构不支持它是平铺的任务列表没有树形结构跨线程计时不支持非线程安全不能共享给多个线程高精度纳秒级支持底层用System.nanoTime()精度足够业务用自动输出到日志框架不支持只返回字符串打印得你自己来这张表里最关键的两行是“嵌套计时不支持”和“跨线程不支持”。我见过有人想把一个 StopWatch 塞进 ThreadLocal 里跨线程复用结果数据错乱也见过有人试图用它表达“A 任务里包含 B 和 C”的层级关系最后发现prettyPrint()输出的是一串平铺的行看不出父子。它就是个扁平的秒表集合认清这一点用起来就不会别扭。底层实现上它内部维护了一个ListTaskInfo每次start(taskName)就往里加一个任务并记录起始纳秒数stop()时把结束纳秒数补上。调用getTotalTimeMillis()时把所有任务的耗时累加。注意这里是累加不是“从第一个 start 到最后一个 stop 的墙上时间”。这个差异在多任务串行执行时没影响但如果你中间有空档比如 start 了任务 Astop 之后隔了一会儿才 start 任务 B总耗时里不包含那段空档。这个特性在做分段统计时反而是优点——你统计的就是各段实际干活的时间。2.2 三个必知的行为细节第一个细节未 stop 就调用 prettyPrint 会抛异常。源码里prettyPrint()会检查isRunning()如果还有任务处于运行中状态直接抛IllegalStateException。这个设计挺合理防止你统计出半截数据但调试时容易踩——尤其是 try-catch 里忘了在 finally 中 stop 的情况。第二个细节keepTaskList 参数。构造函数new StopWatch(taskName)和new StopWatch(taskName, false)的区别在于是否保留任务列表。传false时内部不存TaskInfo只累加总耗时此时调getTaskCount()、prettyPrint()拿不到明细。什么时候用它当你只关心“总共花了多久”、不关心分段明细又想省一点点内存和对象创建开销时。不过在业务代码里这点开销可以忽略我一般还是保留列表方便排查。第三个细节重复 taskName 不会被拒绝。你完全可以连续start(查询)两次它会生成两条同名记录prettyPrint()里两行都叫“查询”。这既是灵活性也是坑——如果你在循环里 start 却没对应 stop或者重试逻辑里重复 start日志里就会出现一堆同名任务看着像数据错了。我的习惯是任务名带上序号或关键参数比如queryUser#1001出了问题能对上具体是哪次调用。注意StopWatch 的start()在已经 running 的状态下调用会抛IllegalStateException(Cant start StopWatch: its already running)。所以“分段计时”不能靠反复 start 实现必须先 stop 再 start 下一个任务。第一次用的人几乎都会在这里卡一下。3. 把计时埋进接口从零到可用的完整过程3.1 依赖与环境确认Spring 项目基本自带 spring-core不需要额外引包。非 Spring 项目想单独用这个类可以只引核心包。用 Maven 的话确认一下dependency groupIdorg.springframework/groupId artifactIdspring-core/artifactId version5.3.31/version /dependency版本号按你项目实际的 Spring 版本走别硬套上面的。判断能不能直接用最简单的办法是在 IDE 里敲new StopWatch()看能不能自动 import 到org.springframework.util.StopWatch能就说明依赖已经在了。我试过在一个纯 Java 的定时任务工程里单独引 spring-core为了一个 StopWatch 拖进来几百 KB 的包虽然能跑但有点浪费这种场景我最后换成了自己封装的 20 行计时工具类。所以选型上有个判断标准项目里已经有 Spring 就用它没有就别为了它引 Spring。另外提醒一句JDK 版本不影响用法但从 Java 8 往上都稳。有一个小细节StopWatch用的是System.nanoTime()这个方法在虚拟机里返回的是单调递增的纳秒数不受系统时间调整影响比currentTimeMillis()可靠。这一点在做耗时统计时很重要——currentTimeMillis()在服务器时间同步、时区调整时可能往回跳算出来的耗时会变成负数。3.2 一个最小可用的分段计时骨架先看最朴素的用法建立直觉public UserVO queryUser(Long userId) { StopWatch sw new StopWatch(queryUser); try { sw.start(参数校验); validate(userId); sw.stop(); sw.start(查数据库); UserDO user userMapper.selectById(userId); sw.stop(); sw.start(对象转换); UserVO vo convert(user); sw.stop(); return vo; } finally { if (sw.isRunning()) { sw.stop(); } log.info({} 耗时明细:\n{}, queryUser, sw.prettyPrint()); } }这段代码有几个点值得说。第一new StopWatch(queryUser)里的 id 会出现在prettyPrint()的第一行标识这次统计属于哪个逻辑建议用方法名。第二finally里先判断isRunning()再 stop这是防御性写法——如果validate抛异常sw.stop()那行不会执行StopWatch 会卡在 running 状态此时直接调prettyPrint()就抛异常了整个 finally 块挂掉把原始异常给覆盖了排查起来极其痛苦。第三日志用\n拼接而不是直接当参数传是因为prettyPrint()本身是多行文本用占位符输出会有缩进问题实际项目里我用的是log.info(...{}, sw.prettyPrint())加一个换行前缀或者干脆分两行打。3.3 任务命名与粒度的取舍计时点的粒度直接决定日志有没有用。切太粗一个方法一个 StopWatch只能知道总耗时定位不到瓶颈切太细每个 getter 都计一次日志爆炸反而看不清。我的经验是按“可能成为瓶颈的独立动作”来切数据库访问、远程调用、文件读写、复杂计算、大循环、序列化转换这几类各占一个 task。业务逻辑的 if-else 判断不要单独计时那玩意儿纳秒级计了也没意义。命名上我踩过的坑是用了中文任务名prettyPrint()输出时列宽会错位对齐很难看。后来统一改成英文短名比如validate、db、rpc、convert、cache日志整齐多了。如果你团队要求中文也不是不行就是接受格式不完美。下面是我现在常用的命名约定任务名对应动作出现频率validate参数校验、权限判断每条请求cache.get缓存读取视业务db.query/db.update数据库读写高频rpc.xxx远程服务调用中频convertDO/VO 转换、序列化每条请求loop.process批量处理循环批量接口任务名前面加个类别前缀db.、rpc.日志里扫一眼就知道哪一类占了大头比一堆无前缀的名字好读。这个约定不用写进规范团队里口头说一次基本就能统一。3.4 一个容易忽略的坑异常分支的耗时正常路径计时很直观异常路径才是麻烦所在。考虑这个场景sw.start(db.query)之后mapper 抛了超时异常代码跳进 catch。此时db.query这个任务还处于 running你没法再 start 下一个任务prettyPrint()也会抛异常。更糟的是你可能想在 catch 里记录“失败发生在哪一步”但 StopWatch 的 API 没有“记录失败标记”的能力。我的处理方式是在每个可能抛异常的动作外面套一层用try-finally保证 stop 一定执行sw.start(db.query); try { user userMapper.selectById(userId); } finally { sw.stop(); }这样即便查库超时抛异常db.query的耗时也会被记录下来记录的是到抛异常为止的时间prettyPrint()能正常输出日志里就能看到“这个请求在 db.query 上耗了 3000ms 然后失败”。这个信息在排查超时类问题时价值极高——你能区分“是查库慢导致超时”还是“查库瞬间失败但后面某段逻辑挂起”。虽然多写两行try-finally有点啰嗦但在关键路径上我认为完全值得。4. 慢接口定位把计时数据变成判断依据4.1 什么样的日志才算“能定位问题”很多人加了 StopWatch日志打出来长这样StopWatch queryUser: running time 812345678 ns --------------------------------------------- ns % Task name --------------------------------------------- 620000000 076% db.query 150000000 018% convert 42000000 005% 其他看着挺专业但实际排查时发现没法用ns 这个单位对人不友好百分比是三位数格式076%而且任务名和耗时的对应关系要一行行对。prettyPrint()有另一个重载prettyPrint(long timeUnitMillis)或者直接用getTotalTimeMillis()自己拼。我现在的做法是自己格式化不用默认输出private String formatStopWatch(StopWatch sw) { StringBuilder sb new StringBuilder(); sb.append(total).append(sw.getTotalTimeMillis()).append(ms); for (StopWatch.TaskInfo task : sw.getTaskList()) { sb.append( | ).append(task.getTaskName()) .append().append(task.getTimeMillis()).append(ms); } return sb.toString(); }输出变成一行total812ms | db.query620ms | convert150ms | validate3ms。一行日志的好处是能被日志采集系统按字段切分后面做聚合分析、画耗时分布图都方便。多行文本在 ELK 或者类似系统里会被拆成多条反而不好查。这个改动很小但收益很大我建议你一开始就这么做。4.2 用占比判断瓶颈而不是看绝对值拿到分段耗时后判断瓶颈的标准不是“哪个任务绝对耗时最长”而是看占比和波动。举个我实际遇到的例子某查询接口平均耗时 200ms日志显示db.query120ms、convert60ms、validate5ms。绝对值看 db 最大直觉上该优化 SQL。但我拉了一段时间的日志做对比发现convert在数据量大的时候会飙到 300ms 以上而 db 始终稳定在 120ms 左右。最后优化的是转换逻辑把反射拷贝换成手写 setter接口 P99 从 800ms 降到 260ms。这个例子说明单次日志只能看结构多次日志对比才能看出来源。所以我建议给计时日志加上可筛选的标识比如 URL、用户 ID 的哈希、数据量大小方便你把“慢的那些请求”捞出来看它们的共同特征。比起盯着一条日志琢磨把 100 条慢请求的convert耗时拉出来看分布结论会清晰得多。下面这张表是我总结的判断思路遇到慢接口可以直接套现象可能原因下一步动作某个任务占比稳定超过 60%该环节是主要瓶颈专项优化这个环节各任务占比均衡但总耗时高任务数量多、单次开销累积合并调用、减少交互次数同一任务耗时波动极大缓存命中率、数据量、锁竞争看波动与什么参数相关总耗时远大于各任务之和任务间空档耗时未统计补充计时点别漏段计时日志缺失异常路径没走到 finally检查 try-finally 覆盖最后一行需要特别说明。如果你发现某类请求的计时日志完全没打出来八成是异常在finally之前就把整个方法抛穿了或者日志级别被过滤了。前者要在 finally 里做好兜底后者去查 logback 配置。4.3 采样与开关别让计时拖垮性能StopWatch 本身开销极小一次 start/stop 就是两次nanoTime()调用加一次对象创建单次在百纳秒级。但如果你在高频接口QPS 几千里每条都创建对象、拼字符串、打日志那日志 IO 和 GC 压力就不可忽略了。我实测过一个 QPS 3000 的接口全量开启计时日志后CPU 使用率涨了大约 8%GC 频率也有上升主要是字符串拼接和日志刷盘带来的。所以我的做法是可开关 采样。开关用配置中心的一个布尔值控制默认关排查问题的时候打开采样则是对高 QPS 接口只给 1% 的请求打计时日志。实现上很简单if (stopWatchEnabled ThreadLocalRandom.current().nextInt(100) 0) { // 才创建 StopWatch 并计时 }注意判断条件要放在方法最前面避免创建了对象却不用。另外计时点的代码会侵入业务方法如果这个接口本身很干净、不想被污染可以退一步用 AOP 拦截整个方法只在方法级别计时——粒度粗了但零侵入。两种方式我都在用核心接口用显式埋点粒度细边缘接口用 AOP省事。选哪种看你对这个接口的重视程度。提示采样率不要固定死最好也做成配置项。平时 1%或者干脆 0怀疑有问题时临时调到 50% 甚至 100%排查完调回来。这个操作不需要发版用配置中心推送即可非常灵活。5. 常见问题与踩坑实录5.1 问题速查表问题现象根因解决办法抛IllegalStateException: Cant start StopWatch上一个任务没 stop 就 start 新的检查每个 start 是否有对应 stopprettyPrint()抛IllegalStateException有任务处于 running 状态finally 里判断isRunning()后 stop总耗时比预期小很多任务间空档时间不计入给空档也起个任务名或者接受这个语义任务名重复出现多行循环或重试里重复 start 同名任务任务名加序号或改到循环外计时日志里百分比是三位数prettyPrint()的格式化特性自己拼日志不用默认输出多线程下数据错乱StopWatch 非线程安全每个线程各自 new 一个计时结果偶尔为负用了currentTimeMillis()自己算统一改用 StopWatch 或nanoTime()倒数第二行值得展开说。有一次我在一个异步任务里复用了同一个 StopWatch 实例当时想着省对象结果两个线程同时 start/stop任务列表里出现了时间交错、耗时算成负数的诡异数据。排查了大半天才定位到是共用实例的问题。记住一条铁律StopWatch 是“一次请求一个实例”绝不跨线程共享。需要在线程池里计时就在任务内部 new用完丢弃别搞池化。5.2 两个独家心得第一个心得把 StopWatch 的输出和异常信息绑在一起。慢接口往往伴随异常比如超时、连接池耗尽如果计时日志和异常栈分开打排查时要把两条日志按时间戳对上很麻烦。我的做法是在 catch 块里把耗时明细拼进异常消息或者日志一起打catch (Exception e) { log.error(请求失败, 耗时明细{}, formatStopWatch(sw), e); throw e; }这样一条日志就包含了失败原因和耗时分布看日志的人不用来回翻。代价是日志变长但排查效率提升明显。第二个心得给关键任务加耗时告警阈值。单纯的日志是被动的得有人去看。可以在 finally 里判断总耗时超过阈值比如 500ms时打 WARN 级别这样日志系统里按级别一筛就能捞出所有慢请求不用全文检索。如果团队有日志告警平台还能配置“WARN 级别 xx 条/分钟”触发通知。这个成本很低但能让你在用户投诉之前发现问题。5.3 什么时候该换工具StopWatch 不是万能的遇到下面几种情况我会果断换工具需要看方法内部的调用栈分布换 async-profiler 或者火焰图类工具StopWatch 只能给你“我埋了点的地方”看不到没埋点的地方。需要跨线程、跨服务的链路追踪那是分布式追踪的范畴TraceID 那一套StopWatch 只能管单线程单方法。需要长期、低开销的运行监控用指标采集计数器、直方图StopWatch 的字符串输出不适合做时序数据。需要统计锁等待、GC 停顿这些在 JVM 层面业务代码里埋点测不准。用一句话概括StopWatch 是“我能想到在哪里慢所以我在那里放个秒表”它依赖你的先验判断而 profiler 是“我不知道哪里慢让工具告诉我”。两者不冲突日常排查先从 StopWatch 的日志看结构看不出来再上 profiler这个顺序我用了几年效率最高。最后分享一个实际体会这套东西价值不在代码本身就几十行而在于你愿不愿意坚持给核心接口加埋点、并且定期回头看日志。我见过太多项目埋点加了日志打了但没人看出问题时还是靠猜。真正有效的是把“慢请求日志”纳入日常巡检每周扫一眼有没有新出现的耗时大户把问题掐在萌芽阶段。工具是死的习惯才是那个让工具产生价值的东西。