急急急！耗时日志与打印日志时间对不上
代码是用组里同事用scala写的，编译运行在jvm；
背景是线上反应某接口响应时长P99耗时太长，将接口从头到尾的运行耗时打印出来，发现经常出现以下情况：
最下面的红框打印的是整个方法的耗时显示200多ms,红框以上打印了该方法内每一步的耗时，从step1到step7,从中可以看到方法内每步操作都不超过1ms,但是方法整体耗时却超过200ms;
我通过查看最左边的红框和右边的第一个红框，对比得出step2虽然打印耗时很短，但是step1和step2的日志打印日志却相差200多ms,所以就出现了标题所描述的日志的打印时间和耗时打印不一致的情况。
但是重新请求却发现没有复现，整个方法都几毫秒就跑完了，而且step1和step2之间并没有其他操作，step2也只是获取redis的数据一个操作而已。
当时怀疑是redis的问题，目前已经排除了redis响应时长和连接时长问题。
求大佬指点一个排查方向！！！
回答：
首先你要确保你打印的日志耗时计算没有问题，
然后日志输出是设置的同步还是异步，时间会存在有一点小的偏差
然后就是你每一步之间也会存在耗时的情况，比如时间片用完了，然后下一步刚刚没有抢到CPU的执行权那就得等待，这个是存在耗时的，但是这种多测几次一直是那样就是程序问题，CPU的情况只是偶尔出现才正常。
还有你说的redis，你redis的调用应该在某一步里噻，所有如果redis连接响应时长和连接时长问题，那么那一步的时长也会边长
回答：
Java里面有2个很不错的轮子，为啥你还在Log。。。
- Commons-lang3
StopWatch - Spring
StopWatch
用法可以参考这里：demo
这玩意儿还能给你展示每个步骤的百分比哦！
以上是 急急急！耗时日志与打印日志时间对不上 的全部内容， 来源链接： utcz.com/p/944277.html
