写业务代码的时候我有个习惯凡是一个方法里超过三次调用外部资源数据库、缓存、远程接口就会顺手加一层耗时统计。早年我用的都是最土的办法——long start System.currentTimeMillis()开头一行结尾再减一下打印出来。四五个步骤下来方法体里横七竖八躺着十几行计时变量命名从start1排到start5过两个月自己回头看都要愣一下。后来在 SpringBoot 项目里换成了框架自带的StopWatch工具类同样的事情变成一句sw.start(xxx)加一句sw.stop()日志里还能直接打出一张带占比的耗时表排查慢接口的效率提升非常明显。这篇就围绕 SpringBoot 里的 StopWatch 展开把它能干什么、怎么用、哪些地方会翻车、什么场景该换别的方案一次讲透。适合写过几个 CRUD 接口、但还没系统整理过耗时统计手段的同学也适合已经在用 StopWatch 但只用了一半功能的同行对照看看。1. 从三十行手写计时代码到一行 StopWatch我为什么换工具1.1 手写计时代码在真实项目里会烂成什么样先说手写方案的问题不吐不快。我经手维护过一个报表组装接口单次调用要串行跑六七个数据源用户基础信息、订单列表、退款记录、标签画像、推荐位素材最后还有一步模板渲染。原作者为了看清每步耗时在方法里塞了十几个System.currentTimeMillis()调用变量名分别是t1、t2、t3……一直到t7中间还嵌套了一层 try-catch。这段代码的三个致命伤我在后续改需求时全踩了一遍第一步骤顺序一调整所有变量名和时间差表达式都要跟着重排漏改一处打印出来的耗时就是负数或者几十个小时第二任何一步抛异常后面所有的差值计算全部作废日志里只剩一个空指针堆栈根本看不出是哪一步先慢下来的第三耗时明细是以六行独立日志打出去的日志平台按 traceId 检索时六行散落在不同位置人工拼接特别费劲。手动计时还有个隐性成本它把业务逻辑和观测逻辑揉在了同一层。你要读业务得先跳过一堆计时语句你要调计时又得小心别改坏业务分支。方法体越写越长最后谁也不敢删那几行计时因为可能还有用。这才是最糟糕的结局——观测代码变成了技术债。StopWatch 解决的正是这个结构问题它把记录任务名、开始时刻、结束时刻、累计总时长这件事收进一个对象你只需要在业务语句前后各插一行剩下的格式化、求和、算百分比全由它负责。1.2 StopWatch 替我们兜住的四件事具体拆开看这个工具类帮我兜住了四件事每一件都对应手写方案的一个坑。第一件任务名与耗时的绑定。每次start(任务名)会创建一个带名字的任务记录stop()时把耗时写回这条记录。这样日志里输出的不是第 3 段耗时 120ms而是assemble 耗时 120ms可读性差了一个量级。第二件累计总时长自动求和。getTotalTimeMillis()直接返回所有已完成任务的耗时之和不用自己维护累加变量。要知道在并发场景下自己维护累加变量是很容易出错的。第三件格式化输出。prettyPrint()会生成一张包含任务名、耗时、百分比占比的文本表格哪一步吃掉了大头一眼就能看出来shortSummary()则是把所有任务压成一行适合塞进单行日志。第四件状态校验。没start就stop()或者前一个任务还没stop()就急着start下一个都会直接抛IllegalStateException。这个设计乍看是限制实际上是在帮你提前发现配对错误——手写方案里时间差算错是静默的而 StopWatch 会把错误当场暴露在开发阶段。注意这个抛异常的特性也意味着你在 for 循环里批量计时时必须保证严格配对否则第一轮跑通、第二轮就炸的情况很常见具体见 2.3 节。1.3 Spring 自带的 StopWatch 与 commons-lang3 那个重名类别搞混这是新手最容易迷糊的一点。StopWatch这个类名至少有两个主流实现一个是org.springframework.util.StopWatch随 spring-core 一起进来另一个是org.apache.commons.lang3.time.StopWatch。两者 API 差异不小检索资料时混着看代码必然编译不过。我做了一张对照表方便你按需选型维度Spring 的 StopWatchcommons-lang3 的 StopWatch是否支持多任务命名支持可记录多个具名任务不支持只记一个总时长是否支持分段拆分不支持 split支持split()/unsplit()是否支持暂停恢复不支持支持suspend()/resume()能否直接切换时间单位只能取毫秒/秒getTime(TimeUnit)任选依赖来源SpringBoot 项目零引入需额外依赖 commons-lang3典型用途方法内多步骤耗时拆解单段执行时长测量、限流重试间隔选型逻辑其实很简单你要的是一个方法里分几步各花多久用 Spring 的你要的是这一段整体跑了多久、中间能不能暂停用 commons-lang3 的。在 SpringBoot 项目里做接口耗时拆解绝大多数情况都是前者因为依赖已经在了不用额外引包而且它天生贴合分段统计这个诉求。我自己项目里两个都有但分工明确Spring 的用在 Service 层的步骤拆解commons-lang3 的用在定时任务的单轮耗时统计和重试间隔控制。2. 起步把 StopWatch 塞进一个 Service 方法2.1 依赖从哪里来Spring Boot 项目其实是零引入很多人第一次搜StopWatch 依赖会搜到一堆 Maven 坐标其实完全没必要。org.springframework.util.StopWatch属于 spring-core 模块而任何 SpringBoot 项目的spring-boot-starter-web、spring-boot-starter-data-redis、spring-boot-starter-jdbc这些 starter 都会传递依赖进 spring-core。也就是说只要你的项目能启动 Spring 容器这个类就一定在 classpath 里直接import就能用。验证方式也很简单在 IDEA 里敲import org.springframework.util.StopWatch;能正常补全且不标红就说明依赖齐了。如果标红说明你的工程压根不是 Spring 工程或者用了很旧的依赖裁剪方式那时候要做的不是加坐标而是先确认项目结构。唯一需要留意的是版本差异。Spring Framework 5.x对应 SpringBoot 2.x的 StopWatch 内部用System.currentTimeMillis()计时精度是毫秒Spring Framework 6.x对应 SpringBoot 3.x改成了System.nanoTime()纳秒计时prettyPrint()的表头也从ms变成了ns。这个差异会直接影响你读日志时的心算习惯我在 5.3 节会专门展开。写代码前花两分钟看一眼自己项目里这个类的源码比记任何博客都靠谱。2.2 最小可用示例与它的真实输出先上一个能直接跑的最小例子。假设有个报表组装服务内部三个步骤Service public class ReportService { private static final Logger log LoggerFactory.getLogger(ReportService.class); public ReportVO buildReport(Long userId) { StopWatch sw new StopWatch(buildReport# userId); try { sw.start(loadUser); User user userMapper.selectById(userId); sw.stop(); sw.start(loadOrders); ListOrder orders orderMapper.selectByUserId(userId); sw.stop(); sw.start(assemble); ReportVO vo assemble(user, orders); sw.stop(); return vo; } finally { if (sw.isRunning()) { sw.stop(); } log.info(report cost detail:\n{}, sw.prettyPrint()); } } }构造参数buildReport# userId 是给这个 StopWatch 起个标识它会出现在输出表头。这个标识千万别写死成常量否则日志里几十个请求混在一起完全分不清。我的习惯是方法名#关键入参方便按用户维度追踪单次慢调用。跑出来的prettyPrint()大致长这样5.x 版本单位毫秒StopWatch buildReport#10086: running time (millis) 187 ----------------------------------------- ms % Task name ----------------------------------------- 00045 024% loadUser 00120 064% loadOrders 00022 012% assemble6.x 版本的表头换成ns数值会大六七个数量级比如45123456 24% loadUser。两种都能用关键看占比列。这张表的读法比很多人想的有讲究先看占比再看绝对值。上例里loadOrders占了 64%是绝对瓶颈优化应该从这里下手而不是去抠assemble那 22 毫秒。我见过不少同学看到总耗时 187ms 就急着去改渲染逻辑结果改了半天总量只降了 5 毫秒——因为方向从一开始就错了。2.3 start/stop 的配对规则与两个必抛异常StopWatch 的状态机只有两态运行中和空闲。规则就三条但每一条都有对应的异常空闲态调start(name)进入运行态创建一个新任务记录。运行态调stop()回到空闲态把耗时写进当前任务并追加到任务列表。运行态再调start(name)抛IllegalStateException(Cant start StopWatch: its already running)空闲态调stop()抛IllegalStateException(Cant stop StopWatch: its not running)。第一个异常在循环里最容易踩。假设你要批量处理 100 个商品每个商品算一次耗时// 错误写法第一轮之后必炸 StopWatch sw new StopWatch(batch); for (Product p : products) { sw.start(calc- p.getId()); // 第二轮这里抛异常 calculate(p); sw.stop(); }正确做法是每次循环都new StopWatch()或者老老实实改成一次 start、中途不拆的结构。如果确实需要统计每一轮的耗时还有一种写法是不用任务名自己在循环外维护 List每轮 new 一个新的 StopWatch 只测单次。我一般选后者因为批量场景下你关心的是单次耗时的分布中位数、P99而不是某一轮里的步骤拆解。第二个异常更隐蔽在finally里无脑stop()。如果异常发生在第一个start()之前比如参数校验失败直接抛出进finally时 StopWatch 还处于空闲态stop()会再抛一个异常把原始异常给吞了——这是排查线上问题时最让人崩溃的情况之一堆栈里只剩一个莫名其妙的IllegalStateException真正的业务异常无影无踪。所以finally里必须先判断状态finally { if (sw.isRunning()) { sw.stop(); } log.info(...); }这段if是我认为使用 StopWatch 最不能省的一行代码。它不只是防止二次抛异常还有个附带好处如果业务在中途异常正在运行的那个任务会被正常stop并记入列表日志里就能直接看出是哪一步炸的、炸之前已经跑了多久。这比单纯打一个异常堆栈信息量大得多。3. 输出格式改造让耗时数据从能看到能查3.1 prettyPrint 的多行输出为什么在日志系统里很难受prettyPrint()生成的是多行文本人眼看着舒服但在现代日志体系里会遇到两个麻烦。第一个麻烦是日志采集的断行。多数日志收集组件是以一行一条记录为单位做索引的多行输出要么被拆成七八条独立记录要么需要额外配置多行合并规则按开头关键字聚合。前者会让你的耗时表和它的上下文traceId、请求参数、异常堆栈在检索结果里被割裂开后者需要在采集端配正则一旦哪天有人把输出格式微调了合并规则就失效日志直接散架。我在两个项目里都因为这个问题被折腾过后来干脆自己拼一行。第二个麻烦是无法做聚合统计。多行文本里的数字日志平台没法直接当数值字段用你没法在面板上画loadOrders 的 P99 耗时趋势只能肉眼看。而单行的 keyvalue 格式采集端配个正则就能提取成结构化字段趋势图、告警阈值全都能挂上去。结论很明确本地调试用 prettyPrint线上环境用自定义单行输出。这两者不冲突完全可以根据环境变量或者日志级别切换。3.2 自己拼一行结构化日志的完整代码我常用的格式化方法是这样几十行代码直接抄public class StopWatchFormatter { public static String oneLine(StopWatch sw) { StringBuilder sb new StringBuilder(160); sb.append(cost id).append(sw.getId()) .append( total).append(sw.getTotalTimeMillis()).append(ms) .append( taskCount).append(sw.getTaskCount()); if (sw.isRunning()) { sb.append( runningtrue); } for (StopWatch.TaskInfo task : sw.getTaskList()) { sb.append( | ).append(task.getTaskName()) .append().append(task.getTimeMillis()).append(ms); } return sb.toString(); } }打出来的样子cost idbuildReport#10086 total187ms taskCount3 | loadUser45ms | loadOrders120ms | assemble22ms单行、字段清晰、任务名和耗时成对出现采集端拿|和两个字符就能切出结构化字段。这里有两个细节必须提醒。第一getTaskList()有前置条件只有keepTaskList为true时才有数据如果调用过setKeepTaskList(false)再取任务列表会抛UnsupportedOperationException。默认值是true所以大多数人不会遇到但如果你为了省内存主动关了它就别再调用getTaskList()和prettyPrint()——后者内部也依赖任务列表。第二TaskInfo的方法在不同版本里不一样。5.x 只有getTimeMillis()和getTimeSeconds()6.x 增加了getTimeNanos()。跨版本升级时这块编译会报错别以为是自己的问题。还有个常见的选型纠结用id还是getLastTaskName()getId()返回构造时传的标识getLastTaskName()返回最后一个任务的名字。前者是这次调用的身份后者是最后一段干了什么用途完全不同别混着用。3.3 从占比列里读出真正的瓶颈拿到耗时表之后怎么读才算读到位我总结了一个三步法。第一步看总量是否符合预期。比如接口对外承诺 500ms 内返回实际总量 1200ms那就是超标必须拆。但如果外部调用本身就有 SLA 说明是 800ms那这个数字其实是正常的问题在别处不该盲目优化。第二步找占比超过 30% 的任务。上面那个例子loadOrders占 64%优先看它。是 SQL 没走索引是返回结果集太大是一次性拉全量没做分页每一个都能对应到具体的改法。第三步看那些看着很小但次数很多的任务。这是容易被忽略的一类。我遇到过一次单个getTag调用只花 0.3 毫秒看起来无足轻重但它在循环里被调了 800 次累计消耗 240 毫秒占总量的四成。这种问题只有在循环外整体套一层 StopWatch 做汇总才能发现光看单次耗时永远找不出来。提示StopWatch 统计的是墙钟时间也就是包含线程阻塞、IO 等待的时间。如果你看到某一段耗时远超 CPU 运算所需先怀疑是锁等待或者网络抖动而不是算法复杂度问题。这是两码事。4. 分层埋点Controller、Service、DAO 各记一段的三种组织方式4.1 一个实例贯穿全链路嵌套任务名怎么起如果整条调用链都在一个线程内串行执行最省事的做法是在入口处创建一个 StopWatch往下传。Controller 层建实例、启动第一个任务Service 层继续start/stop最后在 Controller 的finally里统一输出。这种做法的前提是StopWatch 实例得能传下去。传参有两种方式——显式当方法参数传或者放ThreadLocal。我不推荐 ThreadLocal因为一旦用了线程池、异步、批量并行跨线程就取不到还容易忘记清理导致信息串联。显式传参虽然丑一点但边界清晰谁用谁传不会出幺蛾子。真正需要设计的是任务名规范。全链路共用一个实例时任务名如果随便起日志里会出现一堆query、select、load完全看不出层级。我现在的命名约定是层.方法.动作例如sw.start(ctrl.buildReport); sw.start(svc.loadOrders.page1); sw.start(dao.selectByUserId);好处有两个一是天然带着层级的语义看名字就知道调用发生在哪一层二是做日志聚合时可以直接按前缀分组统计DAO 层总耗时占比。前缀统一了后面加监控面板会轻松很多。这套方案也有明显边界它只适合单线程同步链路。一旦某一段用了Async或者线程池并发拉数据那个线程里的start/stop就作用在另一个对象上了得不到汇总。并发场景的处理方式见 5.2 节。4.2 每层独立实例适合按层做统一统计另一种组织方式是每层各建一个 StopWatchController 建一个统计整个接口Service 建一个统计业务处理DAO 那层用 MyBatis 拦截器或数据源代理自己统计。好处是各层互不干扰某层没打印也不影响其他层坏处是日志条数变多而且各层的时间存在包含关系加起来会大于实际总耗时做报表时容易被人误读成总耗时翻倍。我的取舍标准是临时排查用单实例全链路长期监控用分层独立。前者信息集中适合一次性定位问题后者各层自治适合接监控系统因为不同层级的告警阈值本来就该不同——DAO 层超过 200ms 要告警Controller 层超过 1 秒才告警混在一个实例里反而不好配。分层独立还有一个隐含好处责任划分清楚。某天 DAO 层慢得离谱日志里那个独立实例会直接体现出来甩锅的时候不需要来回拉扯。4.3 用 AOP 自动埋点的实现与它踩不住的地方手写start/stop的方式在方法多的时候维护成本很高——加一个步骤要加两行代码删一个步骤要记得删两行。所以不少人会想到用 AOP 自动埋点。实现不复杂先定义一个注解Target(ElementType.METHOD) Retention(RetentionPolicy.RUNTIME) public interface CostTime { String value() default ; }再写切面Aspect Component public class CostTimeAspect { private static final Logger log LoggerFactory.getLogger(CostTimeAspect.class); Around(annotation(costTime)) public Object around(ProceedingJoinPoint pjp, CostTime costTime) throws Throwable { StopWatch sw new StopWatch(pjp.getSignature().toShortString()); String taskName costTime.value().isEmpty() ? pjp.getSignature().getName() : costTime.value(); sw.start(taskName); try { return pjp.proceed(); } finally { sw.stop(); log.info(cost method{} task{} cost{}ms, pjp.getSignature().toShortString(), taskName, sw.getTotalTimeMillis()); } } }注意Around(annotation(costTime))里的参数名必须和方法签名里的形参名一致否则切面绑不上这是个很常见的低级错误。这套东西看着很美但有几类场景它真的管不住必须提前知道同类内部调用不走代理。同一个类里this.methodB()调用Spring 的代理根本拦不住注解形同虚设。这个坑和Transactional失效是同一个原理。private / final / static 方法切不到。Spring AOP 基于动态代理这几种方法天然不在拦截范围内。异步方法只能算到提交为止。方法上加了Async实际执行在另一个线程切面里proceed()返回时任务可能才开始跑测出来的是提交耗时不是执行耗时。只能测单方法总量测不了内部步骤。一个方法里五个步骤谁慢AOP 给不了答案。所以我的实际做法是两者混用方法级别用 AOP 自动打点方法内部的关键步骤用手写start/stop。前者解决覆盖率问题后者解决精度问题。只靠 AOP 会陷入知道这个方法慢但不知道为什么慢的困境这在排查线上问题时是最难受的状态。5. 并发与长生命周期使用中的四个坑5.1 StopWatch 不是线程安全的这一点必须放在最前面强调。Spring 的 StopWatch 内部维护currentTask、startTimeMillis、taskList这些可变状态没有任何同步措施。多个线程共用一个实例轻则任务耗时错乱、总时长对不上重则因为任务列表并发写入而抛出异常。我踩过一次很典型的事故在一个被多线程反复调用的工具类里把 StopWatch 声明成了成员变量// 错误示范 Component public class DataSyncHelper { private final StopWatch sw new StopWatch(sync); // 共享实例 }单线程测试完全正常压测一开就各种奇怪现象任务名对应的耗时张冠李戴total偶发是负数甚至抛出IllegalStateException: its already running。排查了快两个小时才定位到是共享实例。正确做法只有一条StopWatch 必须是方法内的局部变量用完即弃。它的生命周期就应该是一次调用跨调用复用没有任何收益因为prettyPrint()打完之后这个对象就没价值了。5.2 并发任务计时每个任务一个实例 汇总那并发场景怎么办答案很朴素每个并发单元各自建一个 StopWatch然后在汇总处把结果收集起来。ExecutorService pool Executors.newFixedThreadPool(4); ListFutureString futures new ArrayList(); for (Long userId : userIds) { futures.add(pool.submit(() - { StopWatch sw new StopWatch(user# userId); sw.start(query); query(userId); sw.stop(); return StopWatchFormatter.oneLine(sw); })); } for (FutureString f : futures) { log.info(sub task {}, f.get()); }每个子任务输出一行独立的耗时日志采集端按id字段做聚合就能算出这批任务的耗时分布。这种做法比想办法把所有线程的耗时塞进一个 StopWatch要简单得多也更符合观测系统的实际使用方式——你要的本来就是分布而不是一个加总数字。需要提醒的是子任务里如果抛异常f.get()会抛ExecutionException记得包一层别让一个子任务的失败把整个汇总循环打断。5.3 纳秒还是毫秒版本差异导致的误读前面提过一次这里展开说。Spring Framework 6.x 把内部计时改成了System.nanoTime()prettyPrint()输出的表头从ms变成了ns。如果你从 5.x 的项目里拷了一段日志分析的脚本到 6.x 项目脚本按毫秒解析结果会大出六个数量级看起来像是有个任务跑了三个小时。System.nanoTime()相比currentTimeMillis()的优势是它基于单调时钟不受系统时间调整影响。做过服务器 NTP 校时的同学应该有印象currentTimeMillis()在时钟回拨的瞬间可能算出负数而nanoTime不会。所以这个改动是实打实的进步不只是精度问题。但要注意nanoTime()返回的是一个相对值只适合算差值不能当时间戳用它的起点是任意的。所以如果你把 StopWatch 的输出拿去和业务时间戳做关联需要额外记录一个currentTimeMillis的时间点别指望从 StopWatch 里捞出绝对时间。实际使用上我建议统一在格式化方法里转换成毫秒输出不管底层是哪种精度// 6.x 用 getTotalTimeMillis()它会自动从纳秒换算 long totalMs sw.getTotalTimeMillis();跨版本的项目里这个 API 是稳定的直接用它最省心。5.4 什么时候 StopWatch 就该退场了StopWatch 很好用但它有明确的能力边界。以下三种场景我会果断换别的方案。需要长期指标监控的时候。StopWatch 的输出是日志文本本质是给人看的。如果你想做的是过去 24 小时接口 P99 耗时曲线这种持续性指标应该上带指标的观测组件比如 Micrometer 配合时序数据库它能把耗时分位数、成功率、调用量一起管起来。日志方案做这件事需要自己写解析脚本投入产出比很低。需要链路追踪的时候。一次请求跨了三个服务StopWatch 只能看到本进程内的分段跨进程的调用耗时传不过去。这时候需要的是分布式链路追踪靠 traceId 把各段串起来StopWatch 顶多作为叶子节点的一个补充信息。需要精确到微秒以内的时候。JVM 上的计时本身就有误差StopWatch 已经够用但如果你真要做方法级性能剖析用 JFRJava Flight Recorder或者采样型 profiler能拿到方法级的采样数据比手写埋点全面得多。判断标准其实就一句话StopWatch 定位的是这一次调用慢在哪不是这个系统长期表现如何。把它的位置摆正就不会在不合适的场景里硬凹。6. 沉淀下来的一套计时模板与调用约定6.1 一个能覆盖八成场景的工具封装踩了这么多坑之后我把常用的模式收拢成了一个薄封装。它不是要替代 StopWatch而是把状态判断、异常兜底、格式化输出这三件事固定下来业务代码里只保留纯粹的start/stoppublic class ScopedStopWatch implements AutoCloseable { private final StopWatch sw; private final String logTag; public ScopedStopWatch(String id) { this.sw new StopWatch(id); this.logTag id; } public void start(String taskName) { if (sw.isRunning()) { sw.stop(); } sw.start(taskName); } Override public void close() { if (sw.isRunning()) { sw.stop(); } log.info(cost {}, StopWatchFormatter.oneLine(sw)); } }实现AutoCloseable后可以配合 try-with-resources 用方法结束时自动输出不会出现忘记打日志的情况try (ScopedStopWatch sw new ScopedStopWatch(buildReport# userId)) { sw.start(loadUser); userMapper.selectById(userId); sw.start(loadOrders); orderMapper.selectByUserId(userId); sw.start(assemble); assemble(user, orders); }注意start方法里我加了一句如果还在运行就先 stop的兜底这样连续两次start不会抛异常代价是上一个任务的耗时会以到当前时刻为止计入。这个取舍看场景排查阶段我宁愿它抛异常暴露问题稳定运行阶段我宁愿它宽容一点别把主流程搞挂。所以真实项目里我会把它做成可配置的或者干脆保留严格模式。6.2 日志字段命名与阈值约定最后说几个落地时的约定这些是文档里不会写但团队协作时特别重要的东西。任务名必须有辨识度且不要带随机数。见过有人在任务名里拼UUID结果日志采集端把每个任务名都当成独立维度指标面板上刷出上万个 key直接把时序数据库撑爆。任务名应该是有限枚举变量部分放到id里。阈值要写进代码别只写在文档里。我的做法是在封装里加一个阈值判断超过就升成 WARN 级别日志if (sw.getTotalTimeMillis() 500) { log.warn(slow call {}, StopWatchFormatter.oneLine(sw)); }这样告警链路天然就接上了不用额外配规则。别为了统计而统计。我见过一个项目几乎每个方法都包了 StopWatch日志量翻了三倍磁盘占用飙升但真正有人看的只有那几个核心接口。建议只在外部资源调用、循环批量处理、对外接口入口这三类位置埋点其他地方等真出了问题再加也不迟。我个人在实际操作中的体会是StopWatch 这类工具的价值不在于能算出耗时而在于让耗时数据以低成本的方式被看见。它的门槛低到几乎不会增加代码复杂度正是因为这一点才容易被滥用也才更需要一套约定去约束它。先用起来再在真实的排查场景里慢慢调整埋点位置比一开始就设计一套完美的观测体系要实际得多。