每个环节日志都只有 20 毫秒 接口总耗时 800 毫秒 差在哪

接口总耗时 800 毫秒，日志里从入口到数据库每一步都只写了十几毫秒，中间七百多毫秒找不到出处，只能挨段猜。乍看像缓存或者权限的锅，追下去往往不是。

long t0 = System.nanoTime();
try { return next(); } finally {
  log.info('cost={}ms', (System.nanoTime()-t0)/1000000);
}

追下去是这么回事：埋点只打在方法入口和出口，对象序列化、连接池等待、下游调用之间的空白段没人记录，各段加起来自然对不上总耗时，慢的地方恰好都在没打点的缝隙里。

碰到「接口耗时埋点缺口」这类问题，我习惯先把当前配置原样备份一份，改坏了立刻换回来，不用现场推。接口问题先分清是没发出去、发出去了没收到，还是收到了处理失败。

偶发问题先统计频率，一小时几次和一天一次，查法完全不同。改完顺手把文档补一句，省得下次自己重新推一遍。

具体做法是，在过滤器里统一记入口和出口耗时；把序列化和下游调用单独打点；用差值定位空白段再往细拆。

验收就看一点，各段耗时加起来和总耗时差距在二十毫秒以内。