System.nanoTime()和System.currentTimeMillis()性能问题

Posted 2020-11-20 cord

　　之前给模块做性能优化的时候，需要将性能调到毫秒级，使用了System.nanoTime()和System.currentTimeMillis()对代码分片计时分析耗时操作，后发现在串行情况下性能达到毫秒级，但是一旦在并发压测的时候，性能急剧下降，后经多方排查，发现原因出在System.nanoTime()和System.currentTimeMillis()这两个api上，其在并发情况下耗时会急剧上升，当然在整体上看依然很快，但是在高性能场景下就有很显著的影响。特此记录一下。

　　测试代码:

 1 package cord;
 2 
 3 import java.util.concurrent.CountDownLatch;
 4 
 5 /**
 6  * Created by cord on 2018/5/7.
 7  */
 8 public class SystemApiPerfTest {
 9 
10     public static void main(String[] args) throws InterruptedException {
11         int count = 100;
12         /**并发*/
13        long interval = concurrentTest(count, ()->{System.nanoTime();});
14        System.out.format("[%s] thread concurrent test <nanoTime> cost total time [%s]ns, average time [%s]ns.
", count, interval, interval/count);
15 
16        /**串行循环*/
17        interval = serialNanoTime(count);
18        System.out.format("[%s] count serial test <nanoTime> cost total time [%s]ns, average time [%s]ns.
", count, interval, interval/count);
19 
20        System.out.println("-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-");
21 
22         /**并发*/
23         interval = concurrentTest(count, ()->{System.currentTimeMillis();});
24         System.out.format("[%s] thread concurrent test <currentTimeMillis> cost total time [%s]ns, average time [%s]ns.
", count, interval, interval/count);
25 
26         /**串行循环*/
27         interval = serialCurrentTime(count);
28         System.out.format("[%s] count serial test <currentTimeMillis> cost total time [%s]ns, average time [%s]ns.
", count, interval, interval/count);
29 
30     }
31 
32     private static long concurrentTest(int threads, final Runnable r) throws InterruptedException {
33         final CountDownLatch start = new CountDownLatch(1);
34         final CountDownLatch end = new CountDownLatch(threads);
35 
36         for (int i = 0; i < threads; i++) {
37             new Thread(() -> {
38                 try {
39                     start.await();
40                     try {
41                         r.run();
42                     }finally {
43                         end.countDown();
44                     }
45                 } catch (InterruptedException e) {
46                     e.printStackTrace();
47                 }
48             }).start();
49         }
50 
51         long stime = System.nanoTime();
52         start.countDown();
53         end.await();
54         return System.nanoTime() - stime;
55     }
56 
57     private static long serialNanoTime(int count){
58         long stime = System.nanoTime();
59         for (int i = 0; i < count; i++) {
60             System.nanoTime();
61         }
62         return System.nanoTime() - stime;
63     }
64 
65     private static long serialCurrentTime(int count){
66         long stime = System.nanoTime();
67         for (int i = 0; i < count; i++) {
68             System.currentTimeMillis();
69         }
70         return System.nanoTime() - stime;
71     }
72 }

测试结果如下:

[100] thread concurrent test <nanoTime> cost total time [5085539]ns, average time [50855]ns.
[100] count serial test <nanoTime> cost total time [2871]ns, average time [28]ns.
-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-+-
[100] thread concurrent test <currentTimeMillis> cost total time [7678769]ns, average time [76787]ns.
[100] count serial test <currentTimeMillis> cost total time [4103]ns, average time [41]ns.

串行情况下耗时趋于稳定，但是在并行情况下就不一样了。

因为这两个api都是native方法，涉及到系统层级的调用，与平台有关。

主要原因有两点:

1. JVM使用gettimeofday()而不是clock_gettime()来获取时间戳;
2. 如果使用HPET时间源,gettimeofday()速度非常慢

除此之外，同样的api，在windows平台的性能比linux上快。

具体原因与实现细节可参阅下面这篇文章(可能需要梯子):

http://pzemtsov.github.io/2017/07/23/the-slow-currenttimemillis.html