前言
在参与一些对性能要求较高的服务和特殊接口开发时,往往会去定位一些业务代码的耗时,通常需要写出下面的代码去计算和打印出业务耗时,这样写还经常减错值导致计算错误。
long serviceAStart = System.currentTimeMillis();
serviceA.doSth();
long serviceAEnd = System.currentTimeMillis();
serviceB.doSth();
long serviceBEnd = System.currentTimeMillis();
log.info("serviceA执行耗时:" + (serviceAEnd - serviceAStart));
log.info("serviceb执行耗时:" + (serviceBEnd - serviceAEnd));
spring提供了一个专门对这一块需求的工具类,StopWatch,可以更优雅的统计业务耗时。
正文
StopWatch
直接看例子吧。
// 定义一个计数器
StopWatch stopWatch = new StopWatch("统计接口业务耗时");
stopWatch.start("serviceA");
Thread.sleep(223);
stopWatch.stop();
stopWatch.start("serviceB");
Thread.sleep(433);
stopWatch.stop();
System.out.println(stopWatch.prettyPrint());
可以看到的是,有很详细的服务耗时,总耗时,每个service占比的输出,很详细。
17:39:57.585 [main] INFO com.example.test.stopwatch.StopWatchTest - StopWatch '统计接口业务耗时': running time (millis) = 663
-----------------------------------------
ms % Task name
-----------------------------------------
00226 034% serviceA
00437 066% serviceB
System.currentTimeMillis性能问题
如果我们看StopWatch源码,会发现它同时也是使用System.currentTimeMillis来统计每一次start、stop,最后做了一次汇总。之前看到有博客对并发调用System.currentTimeMillis 这个方法提出了质疑,并且进行压测,发现并发调用时效率很低。
如并发调用System.currentTimeMillis()一百次,耗费的时间是单线程调用一百次的250倍。为什么会这样呢?来到HotSpot源码的hotspot/src/os/linux/vm/os_linux.cpp文件中,有一个javaTimeMillis()方法,这就是System.currentTimeMillis()的native实现。
jlong os::javaTimeMillis() {
timeval time;
int status = gettimeofday(&time, NULL);
assert(status != -1, "linux error");
return jlong(time.tv_sec) * 1000 + jlong(time.tv_usec / 1000);
}
以上代码的解读呢就是:
1.调用gettimeofday()需要从用户态切换到内核态;
2.gettimeofday()的表现受Linux系统的计时器(时钟源)影响,在HPET计时器下性能尤其差;
3.系统只有一个全局时钟源,高并发或频繁访问会造成严重的争用。
解决性能问题
解决这个性能问题,最常见的办法是用单个调度线程来按毫秒更新时间戳,相当于维护一个全局缓存。其他线程取时间戳时相当于从内存取,不会再造成时钟资源的争用,代价就是牺牲了一些精确度。具体代码如下。
public class CurrentTimeMillisClock {
private volatile long now;
private CurrentTimeMillisClock() {
this.now = System.currentTimeMillis();
scheduleTick();
}
private void scheduleTick() {
new ScheduledThreadPoolExecutor(1, runnable -> {
Thread thread = new Thread(runnable, "current-time-millis");
thread.setDaemon(true);
return thread;
}).scheduleAtFixedRate(() -> {
now = System.currentTimeMillis();
}, 1, 1, TimeUnit.MILLISECONDS);
}
public long now() {
return now;
}
public static CurrentTimeMillisClock getInstance() {
return SingletonHolder.INSTANCE;
}
private static class SingletonHolder {
private static final CurrentTimeMillisClock INSTANCE = new CurrentTimeMillisClock();
}
}
而我们如果面临上面使用stopwatch中的System.currentTimeMillis高并发导致的性能问题,则需要自行重写stopwatch的方法了。
结语
这篇文章是为了方便对业务计时而使用stopwatch工具类来统计业务耗时详情,但在查询相关内容时,却发现stopwatch源码中使用到的System.currentTimeMillis有性能问题,于是引入了相关内容,原博客如下:https://www.jianshu.com/p/d2039190b1cb