如果你还在用System.currentTimeMillis()前后夹击算耗时我建议你把这篇看完。Spring 自带一个StopWatch很多人见过它但没用好它。大多数初接触者以为它只是个更好看的时间戳差值实际上它是一个把多个任务耗时记录、汇总、占比分析一次性做完的小工具。花两三分钟读完你排查慢接口时会多一把顺手的尺子。我最早注意到它是在排查一个查询接口为什么从 300ms 变成 800ms 的时候。当时我在代码里到处加日志每个环节打一次currentTimeMillis()差值日志刷了满屏数据还得自己拿 Excel 算占比。后来同事丢了一句用StopWatch啊我才发现这个工具把记录 N 段任务耗时 自动算占比 格式化输出全干完了。1. 别再用手工三件套了StopWatch 到底解决了什么问题1.1 那个用System.currentTimeMillis()手工计时的下午很多 Spring 开发者第一次接触耗时统计都是从这五行代码开始的long start System.currentTimeMillis(); // 业务逻辑A long step1 System.currentTimeMillis(); // 业务逻辑B long step2 System.currentTimeMillis(); System.out.println(A耗时 (step1 - start)); System.out.println(B耗时 (step2 - step1)); System.out.println(总耗时 (step2 - start));这段代码的问题用过的人都有体会任务一多变量名就变成step1、step2、step3差值计算全凭手动加一个任务就要改三行想算某个任务占总耗时百分比还得自己开 Excel。更难受的是日志里只有数字没有任务名过了两天回看日志根本分不清step2到底对应哪段代码。如果你只是临时看一眼某个方法的耗时手工三件套没问题。但要排查一个接口里多个环节的耗时占比这办法就太低效了。1.2 StopWatch 的核心价值任务化记录与汇总Spring 的org.springframework.util.StopWatch把这个过程变成了三件事给任务起名、开始/停止计时、最后统一输出。StopWatch stopWatch new StopWatch(订单详情查询); stopWatch.start(查询订单主表); // 模拟查询数据库 Thread.sleep(200); stopWatch.stop(); stopWatch.start(查询商品信息); // 模拟调用商品服务 Thread.sleep(120); stopWatch.stop(); stopWatch.start(组装返回结果); Thread.sleep(50); stopWatch.stop(); System.out.println(stopWatch.prettyPrint());prettyPrint()输出长这样StopWatch 订单详情查询: running time 370 ms --------------------------------------------- ms % Task name --------------------------------------------- 200 054% 查询订单主表 120 032% 查询商品信息 050 014% 组装返回结果哪个环节慢、慢到什么程度、占总耗时多少一眼就看明白了。这就是 StopWatch 的核心价值它不是简单的时间戳差值封装而是把多个任务的耗时记录 占比计算 格式化输出打包成了一个开箱即用的工具。2. 核心 API 拆解start / stop / prettyPrint 的完整语义2.1 基础用法与任务命名StopWatch的用法非常直观但它有几个容易被忽视的细节。首先是构造方法。无参构造生成的StopWatch默认 id 是空字符串有参构造可以传入一个任务名这个 id 会出现在prettyPrint()输出和toString()里StopWatch stopWatch new StopWatch(支付接口全链路);如果没有给任务命名排查线上问题时你会看到一堆StopWatch : running time ...虽然不影响数据但多接口并发打日志时很难区分是哪条业务链路的耗时。建议始终传入一个可读性强的名称。然后是start(String taskName)这个重载方法会自动为当前任务命名。任务名建议使用名词短语 动作的格式比如查询用户表、调用风控接口、解析响应报文——日志不是你一个人看的队友和未来的你都需要能瞬间理解这段耗时对应什么操作。2.2 关键方法一览方法返回值含义start(String taskName)void开始计时记录任务名stop()void停止计时内部保存耗时和任务名isRunning()boolean判断当前是否有任务在计时currentTaskName()String当前正在进行的任务名getTotalTimeMillis()long所有任务总耗时毫秒getTotalTimeSeconds()double所有任务总耗时秒getLastTaskName()String最后一个完成的任务名getLastTaskInfo()TaskInfo最后一个任务详情getTaskCount()int已完成的任务数量prettyPrint()String格式化输出所有任务的耗时和占比shortSummary()String简短汇总只输出总线时间toString()String内部调用prettyPrint()shortSummary()的组合输出这些方法里getTotalTimeMillis()和getLastTaskInfo()是我日常用得最频繁的。前者用于算总耗时是否超阈值后者用于拿最后一个任务的具体耗时比如记录批量处理中最后一批的处理时长。2.3 源码层面的两个细节时间戳获取与任务 ID 计数去看一眼StopWatch的源码你会发现两个有意思的细节。第一它内部用的是System.currentTimeMillis()不是System.nanoTime()。这意味着 StopWatch 的精度是毫秒级的对方法级、接口级的耗时排查完全够用但它不适合做微基准测试、算法耗时对比这种需要纳秒精度的场景。有人以为 StopWatch 比手工时间戳更高级、精度更高其实不然它赢在组织方式和输出格式上而不是计时精度。第二start()时内部会维护一个currentTaskstop()时生成一个TaskInfo对象存入ListTaskInfo同时累加totalTimeMillis。整个实现只有一百多行代码没有任何魔法所以它在性能上几乎没有额外开销——在需要埋计时放心用不用担心 StopWatch 本身拖慢接口。3. 实战案例一个接口从 300ms 变 800ms如何用 StopWatch 三步定位3.1 场景描述查询订单接口耗时异常有一次线上反馈订单详情接口从原来的 300ms 左右涨到了 800ms 多用户感知明显卡顿。后台没有报错说明不是异常重试导致的。这种静默变慢最难查因为没有报错堆栈只能靠耗时分析。我的做法是在接口入口处加一个StopWatch把方法内的主要步骤按顺序埋点查询订单主表、查询订单明细、查询商品信息、查询用户信息、组装返回体。每一步都调用start()/stop()并命名最后统一打日志。GetMapping(/order/detail) public ResultOrderDetailVO detail(RequestParam Long orderId) { StopWatch stopWatch new StopWatch(订单详情- orderId); stopWatch.start(查询订单主表); Order order orderMapper.selectById(orderId); stopWatch.stop(); stopWatch.start(查询订单明细); ListOrderItem items orderItemMapper.selectByOrderId(orderId); stopWatch.stop(); stopWatch.start(查询商品信息); ListProduct products productService.listByIds( items.stream().map(OrderItem::getProductId).collect(Collectors.toList()) ); stopWatch.stop(); stopWatch.start(组装返回结果); OrderDetailVO vo buildVO(order, items, products); stopWatch.stop(); log.warn(order detail slow: \n{}, stopWatch.prettyPrint()); return Result.success(vo); }注意这里我没有无条件打日志而是用log.warn把耗时输出打出来。这种慢日志策略在流量大的接口上很关键不然每个请求都打日志量会爆炸。3.2 分层埋点DB、Redis、第三方调用分别计时实际运行后的输出很快暴露了问题StopWatch 订单详情-10086: running time 823 ms --------------------------------------------- ms % Task name --------------------------------------------- 302 037% 查询订单主表 289 035% 查询订单明细 210 025% 查询商品信息 022 003% 组装返回结果三个主要环节都有明显膨胀。单个步骤的耗时都不算离谱但加起来就慢了。这说明不是某一条 SQL 突然崩了而是多个环节同时变慢——典型的基础设施性能退化特征。继续往里面挖我在查询订单明细这一步里又嵌套了一个StopWatch把 SQL 执行时间、MyBatis 映射耗时、分页插件处理耗时分开计时。最终定位到是分页插件在数据量达到百万级后count 查询变慢拖累了整体耗时。这就是 StopWatch 的分层埋点威力外层看哪个阶段拖后腿内层看阶段内部哪一步最耗时两级嵌套能快速缩小排查范围。实际排查链路中我通常先在外层找到嫌疑最大的步骤再在嫌疑步骤内部继续埋点最多嵌套两层就够了再多代码就不好读。3.3 结合 AOP 做统一耗时采集手动在业务代码里加 StopWatch 适合临时排查。如果想把耗时统计固化成一种能力建议做成注解 AOP 切面的形式业务代码一行不动切面统一记录耗时。Target(ElementType.METHOD) Retention(RetentionPolicy.RUNTIME) public interface CostTimeLog { String value() default ; }Component Aspect public class CostTimeAspect { private static final Logger log LoggerFactory.getLogger(CostTimeAspect.class); Around(annotation(costTimeLog)) public Object around(ProceedingJoinPoint joinPoint, CostTimeLog costTimeLog) throws Throwable { StopWatch stopWatch new StopWatch(); try { stopWatch.start(costTimeLog.value().isEmpty() ? joinPoint.getSignature().toShortString() : costTimeLog.value()); return joinPoint.proceed(); } finally { stopWatch.stop(); long cost stopWatch.getTotalTimeMillis(); if (cost 200) { log.warn(slow method [{}] cost [{}]ms, costTimeLog.value(), cost); } else { log.info(method [{}] cost [{}]ms, costTimeLog.value(), cost); } } } }这样在需要观察的方法上加上CostTimeLog(订单批量导入)注解切面自动完成计时和慢日志输出。实测下来这套方案非常稳定线上排查性能问题时几乎不用再改代码直接加注解就完事。4. 线上用 StopWatch 必须知道的四五个坑4.1 非线程安全StopWatch 不能作为共享字段StopWatch不是线程安全的。如果一个 StopWatch 实例被多个线程同时调用start()/stop()会出现在任务 A 计时过程中任务 B 的start()把startTimeMillis覆盖掉的情况导致最终耗时数据错乱。这个坑在把 StopWatch 声明成 static 字段时特别容易踩。有人图方便在一次请求里start(查询)另一次请求里stop()输出的总耗时完全不是本次请求的真实耗时就卸载了。正确做法是每个请求、每次调用都 new 一个 StopWatch 实例。StopWatch 本身很轻量创建成本可以忽略不计。如果你发现自己在多线程环境里共用同一个 StopWatch先停下来想想设计是不是有问题。4.2 忘了 stop 会出现什么StopWatch.stop()如果没被调用对应任务的耗时永远记录不到最直接的后果是getTotalTimeMillis()不准确prettyPrint()里少了任务。但如果再次start()前没有stop()会直接抛IllegalStateExceptionjava.lang.IllegalStateException: Cant start StopWatch: its already running这是 StopWatch 最常被吐槽的地方。项目里有一段被 try-catch 包裹的逻辑start()后抛了异常直接跳过了stop()下次start()就炸了。我的习惯是把 stop 放在 finally 里保证任务无论成败都会结束计时stopWatch.start(调用风险控制接口); try { boolean pass riskService.check(order); // 处理结果 } finally { stopWatch.stop(); }这样既能记录耗时又能避免中断导致的 IllegalStateException。4.3 prettyPrint 的格式与日志输出建议prettyPrint()输出的占比值是四舍五入后的整数百分比多个任务的百分比加在一起可能不等于 100比如 55% 32% 14% 101%。这不是 bug是精度的正常损耗。日志里看到占比是 101% 或 99% 时心里有数别当问题处理。另外prettyPrint()输出是用固定宽度对齐的在 IDE 控制台里很好看但到了日志文件里可能存在特殊字符对齐问题建议直接把prettyPrint()的输出当作一个整体打印不要手动拼字符串处理。如果你只想记录总耗时用shortSummary()就够了输出形如StopWatch 订单详情-10086: running time 823 ms这个格式很干净适合打在 info 日志里。4.4 慢日志阈值不要给每个接口都无条件埋点刚开始用 StopWatch 时我走过弯路——给所有接口都加了 StopWatch并且无条件打印耗时。结果是日志量猛增磁盘 IO 吃紧反而让接口更慢了。后来我调整了策略默认不打印超过阈值才打慢日志。阈值一般按接口的 P95 延迟来定初始可以拍脑袋定个 500ms运行一周后看慢日志量再调整到合适的值。这和使用 APM 工具配置采样率的思路是一样的日志输出也是成本要控制。5. StopWatch 的边界什么场景该换别的工具5.1 高精度场景纳秒级微基准测试前面提到 StopWatch 用System.currentTimeMillis()精度是毫秒级。如果你在写一个工具类想比较两种算法的耗时差异一个算法跑 0.01ms另一个跑 0.03ms用 StopWatch 测出来都是 0ms区别完全看不出来。这种场景应该用 JMHJava Microbenchmark Harness或者至少换成System.nanoTime()自己计时。JMH 能处理 JVM 预热、死代码消除、编译器优化等问题测出来的数据才有参考意义。StopWatch 的定位是业务代码里的耗时观测不是算法性能比拼。5.2 指标聚合场景Micrometer 与监控系统如果要做接口耗时趋势监控、告警、报表StopWatch 就力不从心了。StopWatch 给你的是这一个请求的耗时快照但监控系统需要的是过去一个小时内这个接口 P99 耗时是多少。这时候应该用 Micrometer Micrometer 的Timed注解或Timer.Sample把耗时数据打进 Prometheus、Grafana 等监控平台。// Micrometer 的计时用法和 StopWatch 类似但面向指标系统 Timer.Sample sample Timer.start(registry); // 业务逻辑 sample.stop(registry.timer(order.query.cost));StopWatch 和 Micrometer 可以配合使用局部排查用 StopWatch全局监控用 Micrometer。两者并不冲突。5.3 线上不停机排查Arthas trace还有一类场景代码已经上线不能重新部署加埋点线上又出现偶发慢请求。这时候 StopWatch 帮不上忙因为没埋点上不了数据。我一般会直接用 Arthas 的trace命令在线上动态追踪方法内部各步骤耗时完全不用改代码。trace com.example.service.OrderService queryOrder #cost 500这条命令能直接把OrderService.queryOrder方法耗时超过 500ms 的调用栈及各子方法耗时打出来。Arthas 和 StopWatch 的适用场景完全不同但都是性能排查工具箱里该有的东西。工具精度是否需改代码适用场景Spring StopWatch毫秒需要业务代码内嵌、多任务耗时占比分析System.nanoTime纳秒需要单点耗时精确测量Micrometer Timed毫秒需要监控指标聚合、告警、趋势展示Arthas trace毫秒不需要线上不停机动态追踪JMH纳秒需要算法微基准性能对比StopWatch 不是万能的但它在我日常排查慢接口时的第一反应地位一直没变。一行构造、几段 start/stop、最后 prettyPrint快准狠地把嫌疑锁死在某个环节。我现在的习惯是遇到代码跑得慢的问题先在入口处丢一个 StopWatch跑一遍看占比再决定往哪个方向深挖。这个方法我在多个项目里验证过比到处打印 currentTimeMillis 效率高出不止一个量级。