缓慢的System.currentTimeMillis()

System.currentTimeMillis()性能问题的研究与测试

1. 起因

  今天工作做完了没事干在群里发了张吉冈里帆的比基尼写真图,狗管理说我发黄图禁我言,把我Q群摸鱼的权利都剥夺了,那行吧,刚好把之前测试过的一个东西整理一下记录起来。

  之前学雪花算法的时候看到很多示例会将System.currentTimeMillis()用一个工具类缓存起来再由定时线程去维护,说是System.currentTimeMillis()在高并发下会有性能问题,到底啥问题也没说清楚。按理说Java库中获取低精度时间最基本最常用的方法:System.currentTimeMillis() 还能有啥问题啊,有问题早就炸了还能等到现在吗,所以正好着手测试一下System.currentTimeMillis()的性能和网上的缓存时间戳的办法到底靠不靠谱。

先说结论:然而事实好像真的就是如此,System.currentTimeMillis()这个方法在特定条件下确实可能存在严重的性能问题,但是缓存时间戳的做法问题更大。

2. 分析

  通过测试发现,在Windows下该方法性能表现优秀,在Linux系的操作系统中用TSC、JVM_CLOCK这些更高rating的时钟源性能也没有问题,但是如果是使用HPET、ACPI_PM这类高精度时钟源的时候,高并发下该方法的调用开销明显变高,已经达到了不可接受的地步了(100倍以上的差距)。翻进去我们可以看到System.currentTimeMillis()是一个native方法,意味这个方法的实现取决于异构语言的实现,可能会因为操作系统和安装的JDK不同从而有不同的实现,这也就是解释了为什么在特定条件下会有不同的性能表现,因为不同系统的底层实现不一样嘛。

image.png

  Windows上的黑魔法实现性能非常好,缓存时间戳的方法跟原生比几乎可以说是没有性能优势,但是Windows的分辨率也较低只有0.5ms(这也完全足够用的,毕竟System.currentTimeMillis()本身也只是个低精度时间获取的方法);而Linux上的实现比较复杂,会和系统API打交道开销会比较高,更者如果使用的是HPET这种整个系统共享的时间源,他的API调用在整个计算机上只有不到200万次/s,加上别的开销,差距就会很明显了。

3. 测试过程

通过记录循环调用5000万次System.currentTimeMillis()计算消耗。

public long testSystemMilliSpeed() {
        long sum = 0;
        long t1 = System.currentTimeMillis();
        for (int i = 0; i < 50000000; i++) {
            sum += System.currentTimeMillis();
        }
        long t2 = System.currentTimeMillis();
        System.out.println("[System.currentTimeMillis()] Sum = " + sum + "; time spent = " + (t2 - t1) +
                " ms; or " + (t2 - t1) * 1.0E6 / 50000000 + " ns / iter");
        return sum;
    }
复制代码

测试机器是阿里云计算优化型C6服务器,8核16GB,使用AdoptOpenJDK1.8

系统使用WindowsServer 2019和CentOS 8.2

典型结果示例 Windows

单线程:
[System.currentTimeMillis()] Sum = 7016145501759210272; time spent = 181 ms; or 3.62 ns / iter
[System.currentTimeMillis()] Sum = 7016145521514297836; time spent = 173 ms; or 3.46 ns / iter
[System.currentTimeMillis()] Sum = 7016145533408438385; time spent = 189 ms; or 3.78 ns / iter
复制代码
8线程:
[System.currentTimeMillis()] Sum = 7014845600130793472; time spent = 312 ms; or 6.24 ns / iter
[System.currentTimeMillis()] Sum = 7014845600415181616; time spent = 316 ms; or 6.32 ns / iter
[System.currentTimeMillis()] Sum = 7014845600415181616; time spent = 314 ms; or 6.28 ns / iter
复制代码
16线程
[System.currentTimeMillis()] Sum = 7014831913525842714; time spent = 401 ms; or 8.02 ns / iter
[System.currentTimeMillis()] Sum = 7014831913438052239; time spent = 418 ms; or 8.36 ns / iter
[System.currentTimeMillis()] Sum = 7014831914892399458; time spent = 381 ms; or 7.62 ns / iter
复制代码

小结

  从输出结果可以看出,在Windows下System.currentTimeMillis()的调用开销非常低,每次调用开销只有3.62ns,约等于27亿次每秒,完全可以随性所欲的在任何场景使用。在4个线程的时候甚至性能几乎没有下降,达到了比单线程快约4倍的92亿次每秒,不过再继续加线程的时候单次调用开销就开始变高了,不过性能劣化的并不是很明显,调用的开销可以说是可以完全忽略不计放心使用这个方法。还有就是System.currentTimeMillis()在Windows上的黑魔法实现的代价是分辨率只有0.5ms,他的精度相对于Linux的较低的,不过这本身就不是高精度时间的方法,这一点忽略不计算是Windows上一个优秀的地方。

典型结果示例 Linux(TSC)

单线程
[System.currentTimeMillis()] Sum = 7014846681218501008; time spent = 1308 ms; or 26.16 ns / iter
[System.currentTimeMillis()] Sum = 7014846746587342078; time spent = 1307 ms; or 26.14 ns / iter
[System.currentTimeMillis()] Sum = 7014846811970028463; time spent = 1308 ms; or 26.16 ns / iter
复制代码

8线程

[System.currentTimeMillis()] Sum = 7014815771421781278; time spent = 1563 ms; or 31.26 ns / iter
[System.currentTimeMillis()] Sum = 7014815771870699367; time spent = 1561 ms; or 31.22 ns / iter
[System.currentTimeMillis()] Sum = 7014815774818805007; time spent = 1588 ms; or 31.76 ns / iter
复制代码

16线程

[System.currentTimeMillis()] Sum = 7020243696839914036; time spent = 3147 ms; or 62.94 ns / iter
[System.currentTimeMillis()] Sum = 7020243692320997645; time spent = 3164 ms; or 63.28 ns / iter
[System.currentTimeMillis()] Sum = 7020243700477529928; time spent = 3069 ms; or 61.38 ns / iter
复制代码

小结

  从结果可以明显看出,在使用TSC时Linux上确实是要比Windows明显慢的(该死,Java很多时候就是部署在Linux服务器上...),单线程26ns约3800万次每秒,在线程数小于CPU核心数的时候QPS完全随着线程数增加而提高,跑满8线程之后随线程数的增加QPS达到顶峰不再提高然后单次开销线性提高,开4倍的64线程单次开销同样也是稳定的增加4倍达到120+ns每次,这样的调用开销是完全可以接受的,性能还是非常的优秀可以完全安心的随意使用。

典型结果示例 Linux(ACPI_PM)

单线程

[System.currentTimeMillis()] Sum = 7020093683684623170; time spent = 168303 ms; or 3366.06 ns / iter
[System.currentTimeMillis()] Sum = 7020102078358700323; time spent = 167509 ms; or 3350.18 ns / iter
[System.currentTimeMillis()] Sum = 7020110475654659673; time spent = 168367 ms; or 3367.34 ns / iter
复制代码

8线程

[System.currentTimeMillis()] Sum = 7020137245340372492; time spent = 348907 ms; or 6978.14 ns / iter
[System.currentTimeMillis()] Sum = 7020137258588772567; time spent = 349399 ms; or 6987.98 ns / iter
[System.currentTimeMillis()] Sum = 7020137296734841559; time spent = 351311 ms; or 7026.22 ns / iter
复制代码

16线程

[System.currentTimeMillis()] Sum = 7020205171447447339; time spent = 751769 ms; or 15035.38 ns / iter
[System.currentTimeMillis()] Sum = 7020205162872284276; time spent = 751808 ms; or 15036.16 ns / iter
[System.currentTimeMillis()] Sum = 7020205146376911145; time spent = 751996 ms; or 15039.92 ns / iter
复制代码

结果小结

注:Linux中时间源的分级,HPET、ACPI_PM属于较低的“可用”级别,TSC属于“优秀”的时钟源,KVM_CLOCK属于“理想”的时间源

  因为阿里云ECS上没有注册HPET时间源,边使用了同级别的ACPI_PM时间源同样达到了预期的结果,切换成ACPI_PM时间源之后测试的结果记录恶化我甚至没有办法跑完JMH测试(预计一天都跑不完),直接简单的运行几次获取一些典型结果。

  结果显示开销明显的线性增高,并且随着线程数的增加使用ACPI_PM时性能连Windows的零头都不到,翻了足足一千倍只有约30万次每秒,已经达到了微秒级别的单次调用开销,这样巨大的调用开销可不能被忽略掉,如果项目中刚好有大量使用currentTimeMillis()这个方法,比如说统计每次请求耗时等高频场景则很有可能直接影响到项目的响应时间。

image.png

4. JMH测试

注:由于ACPI_PM太慢了所以没有办法跑完JMH测试,故只有Linux(TSC)和Windows的测试结果

  测试环境使用阿里云最新一代c6计算优化型ECS,配置为8核16G,JDK使用AdoptOpenJDK1.8_u282,操作系统分别是WindowsServer2019数据中心版和CentOS 8.2

  采用上面的示例代码的循环调用方式,每次循环5千万次,分别测试单线程、4、8、16、32、64线程并记录结果统计成表

  结果显示在并发线程数小于服务器核心数时调用开销增加的并不明显,当并发大于等于服务器CPU核心数的时候表现一九比较稳定,随着并发的提高消耗时间稳定增加,currentTimeMillis()这属于CPU密集型的方法,随着CPU满载和并发争抢性能达到饱实际QPS反而下降,属于预期结果。

image.png

如图,在使用ACPI_PM作为时钟源的时候速度实在是太慢了,开16线程的时候性能已经降到了平均16微秒才能执行一次调用,实在无法坚持等到完成测试
image.png

注:测试代码和结果在底部附录

5. 缓存时间戳

  上面提到了我做这次测试的原因,因为看到有些文章、工具包中采用了缓存时间戳代替原生currentTimeMillis()的方式避免了可能的因为不同操作系统带来的不稳定因素,但是这个缓存时间戳的方式靠不靠谱呢?所以同样也得再测试一遍才能下结论。

这是缓存时间戳实现代码:

public class SystemClock {

    private final AtomicLong now;
    private static ScheduledExecutorService scheduler;

    static {
        Runtime.getRuntime().addShutdownHook(new Thread() {
            @Override
            public void run() {
                if (scheduler != null) {
                    scheduler.shutdownNow();
                }
            }
        });
    }

    private SystemClock() {
        this.now = new AtomicLong(System.currentTimeMillis());
        scheduler = Executors.newSingleThreadScheduledExecutor(runnable -> {
            Thread thread = new Thread(runnable, "SystemClockScheduled");
            thread.setDaemon(true);
            return thread;
        });
        scheduler.scheduleAtFixedRate(() -> now.set(System.currentTimeMillis()), 1, 1, TimeUnit.MILLISECONDS);
    }

    public static long now() {
        return getInstance().now.get();
    }

    private enum SystemClockEnum {
        SYSTEM_CLOCK;
        private final SystemClock systemClock;

        SystemClockEnum() {
            systemClock = new SystemClock();
        }

        public SystemClock getInstance() {
            return systemClock;
        }
    }

    private static SystemClock getInstance() {
        return SystemClockEnum.SYSTEM_CLOCK.getInstance();
    }

}
复制代码

吞吐量测试方法和上面System.currentTimeMillis()的测试方法一致,循环调用5千万次,多线程用JMH进行测试

典型结果示例

单线程

## Windows
[BufferClock] Sum = 7014869507792291096; time spent = 16ms; or 0.32 ns / iter
[BufferClock] Sum = 7014869509083652400; time spent = 32ms; or 0.64 ns / iter
[BufferClock] Sum = 7014869510255266345; time spent = 31ms; or 0.62 ns / iter

## Linux(TSC)
[BufferClock] Sum = 7014836520628701408; time spent = 25ms; or 0.5 ns / iter
[BufferClock] Sum = 7014836521867072124; time spent = 25ms; or 0.5 ns / iter
[BufferClock] Sum = 7014836523105825292; time spent = 25ms; or 0.5 ns / iter

## Linux(ACPI_PM)
[BufferClock] Sum = 7014970447687570464; time spent = 25ms; or 0.5 ns / iter
[BufferClock] Sum = 7014970448949515660; time spent = 25ms; or 0.5 ns / iter
[BufferClock] Sum = 7014970450209997473; time spent = 25ms; or 0.5 ns / iter
复制代码

8线程

## Windows
[BufferClock] Sum = 7014837658100506766; time spent = 53ms; or 1.06 ns / iter
[BufferClock] Sum = 7014837658094441788; time spent = 53ms; or 1.06 ns / iter
[BufferClock] Sum = 7014837658032598985; time spent = 56ms; or 1.12 ns / iter

## Linux(TSC)
[BufferClock] Sum = 7020249783930639245; time spent = 51ms; or 1.02 ns / iter
[BufferClock] Sum = 7020249784793206406; time spent = 51ms; or 1.02 ns / iter
[BufferClock] Sum = 7020249784998169933; time spent = 51ms; or 1.02 ns / iter

## Linux(ACPI_PM)
[BufferClock] Sum = 7020287669118903216; time spent = 71ms; or 1.42 ns / iter
[BufferClock] Sum = 7020287669246604147; time spent = 57ms; or 1.14 ns / iter
[BufferClock] Sum = 7020287669311506737; time spent = 64ms; or 1.28 ns / iter
复制代码

16线程

## Windows
[BufferClock] Sum = 7014887357711793536; time spent = 52ms; or 1.04 ns / iter
[BufferClock] Sum = 7014887357711793536; time spent = 53ms; or 1.06 ns / iter
[BufferClock] Sum = 7014887357711793536; time spent = 54ms; or 1.08 ns / iter

## Linux(TSC)
[BufferClock] Sum = 7020240799851649690; time spent = 101ms; or 2.02 ns / iter
[BufferClock] Sum = 7020240798802739189; time spent = 114ms; or 2.28 ns / iter
[BufferClock] Sum = 7020240798701704537; time spent = 118ms; or 2.36 ns / iter

## Linux(ACPI_PM)
[BufferClock] Sum = 7020340267051437045; time spent = 192ms; or 3.84 ns / iter
[BufferClock] Sum = 7020340268861047443; time spent = 144ms; or 2.88 ns / iter
[BufferClock] Sum = 7020340269307897194; time spent = 183ms; or 3.66 ns / iter
复制代码

JMH测试结果

image.png

  这次将currentTimeMillis()的结果和缓存时间戳的测试结果合并再了一起,从结果上看,在线程数超过核心数的时候Linux的斜率要比Windows上高一点,而绿色的和蓝色的缓存时间戳线条完全重合到了一起所以只能看到一条线。

部分过程截图
image.png

结果小结

  从典型结果中可以看出,无论是在Linux还是Windows表现都十分稳定优秀,属于完全没有开销的方法,由此可以看出缓存时间戳的方法确实能够有效的避免因为时间源导致的缓慢问题。

6.残酷事实

  缓存时间戳性能这么好,那我们是不是可以直接使用它来代替JDK的方法了呢?结果是残酷的,缓存时间戳的办法精度不理想也不可控,不建议在任何地方使用(除非你对并发性能有极高要求但是又不在意精度,事实上这种假设不存在)

稳定性测试

  一个获取时间的方法除了要求快,还有个必要前提是它还要准确,如果结果都不准确,那再快都没有任何意义(我心算特快,2352 + 135212 = 97652,啪,我就问你快不快)

测试方法

通过记录一段时间内的调用结果,计算每次ticks间隔的ticks的离散程度

注:因需要一个5亿长度的超大的long类型数组记录调用结果,所以至少需要给JVM分配4GB内存启动

public class TicksTest {

    public static volatile boolean flag = true;

    public static void main(String[] args) {
        TicksTest.step();
    }

    public static void step() {
        // 5亿
        long[] values = new long[500000000];
        // 实现定时500ms
        new Thread(() -> {
            try {
                Thread.sleep(500L);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
            TicksTest.flag = false;
        }).start();

        int length = 0;
        long star = System.currentTimeMillis();
        for (int i = 0; flag && i < values.length; i++) {
            values[i] = System.currentTimeMillis();
//            values[i] = SystemClock.now();
            length = i;
        }
        long end = System.currentTimeMillis();

        // 统计结果
        long min = 0, max = 0, total = 0, minCount = 0, maxCount = 0, totalCount = 0, last = 0, skip = 0;
        List<Long> ticksList = new ArrayList<>(600);
        List<Long> ticksCountList = new ArrayList<>(600);
        for (int i = 1; i < length; i++) {
            if (values[i] != values[i - 1]) {
                long step = (values[i] - values[i - 1]);
                long stepCount = i - last;
                last = i;
                System.out.printf("step %09d %d %d%n", i, step, stepCount);

                // 跳过第一条
                if (skip++ > 0) {
                    total += step;
                    totalCount += stepCount;
                    ticksList.add(step);
                    ticksCountList.add(stepCount);
                    if (max < step)
                        max = step;
                    if (min == 0 || min > step)
                        min = step;
                    if (maxCount < stepCount)
                        maxCount = stepCount;
                    if (minCount == 0 || minCount > stepCount)
                        minCount = stepCount;
                }
            }
        }

        System.out.printf("time: %d, count: %d, " +
                "ticks: (avg: %d, min: %d, max: %d) " +
                "ticksCount: (avg: %d, min: %d, max: %d)",
                end - star, ticksList.size(),
                total / ticksList.size(), min, max,
                totalCount / ticksCountList.size(), minCount, maxCount);
    }

}
复制代码

典型结果示例

这个测试结果是用我自己的开发电脑测试的,配置比较低只有4核16G

currentTimeMillis()

time: 515, count: 512, ticks: (avg: 1, min: 1, max: 1) ticksCount: (avg: 193040, min: 11356, max: 300382)
time: 509, count: 506, ticks: (avg: 1, min: 1, max: 1) ticksCount: (avg: 207048, min: 13123, max: 332162)
time: 513, count: 511, ticks: (avg: 1, min: 1, max: 1) ticksCount: (avg: 208990, min: 3133, max: 330624)
复制代码

缓存时间戳

time: 506, count: 39, ticks: (avg: 12, min: 1, max: 17) ticksCount: (avg: 7673476, min: 62472, max: 11029922)
time: 509, count: 36, ticks: (avg: 13, min: 1, max: 21) ticksCount: (avg: 8133013, min: 22302, max: 13444986)
time: 503, count: 36, ticks: (avg: 13, min: 1, max: 20) ticksCount: (avg: 8624468, min: 48840, max: 13364882)
复制代码

  由结果可以看出,JDK的获取时间戳方法每次ticks都稳定的是1ms,连续多次测试结果一致;而缓存时间戳然后由异步线程每毫秒更新维护的方法ticks十分的不稳定,极少数ticks能正常的是1ms,其他大多数时间都是两位数以上的ticks,真要到了极端的情况给你来个现实中隔20ms调用两次结果都是一样的,你的表情可能要崩溃了;

  还有需要再次强调,currentTimeMillis()的结果取决于底层操作系统,个别操作系统可能是几十毫秒的ticks,这个在JDK方法的注释上已经有说明了,但是目前来看我们常用CentOS、Ubuntu、Depin结果都是足够可靠的。

7. 总结

  currentTimeMillis()方法在Windows下单次调用开销非常低,使用一半CPU线程时单线程QPS最高,然后随着线程数的增加QPS同样提高但不是很线性;Linux中使用TSC时间源时在使用满CPU核心之前QPS线性提高,然后在利用满CPU核心之后QPS达到顶峰不再随着线程数的增加而提高,属于表现十分优秀的方法;在使用ACPI_PM时间源的时候单线程就已经直接跑满了,随着线程数增加QPS并不会提高,而是只能卡着等待currentTimeMillis()的结果,这时候CPU占用也很低,在使用ACPI_PM时底层应该单线程的倒是上层的所有线程都只能排队干等所以才会出现增加线程并不会提高QPS而且CPU占用很低的情况出现。而缓存时间戳实在是一个愚蠢的方案,分辨率太低在高负荷的时候异步更新线程可能无法抢占到CPU时间而导致缓存的时间戳一直不更新,实在糟糕!

  在绝大多数情况下JDK的实现都比绝大多数的人的脑洞实现要可靠的多,请相信JDK,永远不要自作聪明,如果你要耍点小聪明,那么请确保经过详尽可靠的测试验证!

8. 附录

测试代码和结果
github.com/yyyyyzc/cur…

资料参考:
pzemtsov.github.io/2017/07/23/…