时间戳

首页 > 技术文章 > java stopwatch及System.currentTimeMillis使用

java stopwatch及System.currentTimeMillis使用

ls-shiyi 2019-11-16 18:11 原文

前言

        在参与一些对性能要求较高的服务和特殊接口开发时，往往会去定位一些业务代码的耗时，通常需要写出下面的代码去计算和打印出业务耗时，这样写还经常减错值导致计算错误。

    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

推荐阅读