ICode9

精准搜索请尝试: 精确搜索
首页 > 编程语言> 文章详细

深入理解 Java 如何测量时间:从 API 到内核调用

2021-05-30 10:01:49  阅读:161  来源: 互联网

标签:调用 Java currentTimeMillis sys raw API 内核 syscalls nanoTime


问题


即使是最基本的问题,只要打破砂锅问到底也会变得非常有趣。这篇文章,我会深入探究Java如何测量时间。本文从最基础的Java API开始逐层深入:从OpenJDK源代码、glibc,一直到Linux内核。研究各种环境下的性能开销,并尝试对结果进行推理。


文中会探索Java时间测量过程:从某个活动从开始,一直到活动结束经过的时间。对于提高性能、监控操作和强制超时很有帮助。


下面的伪代码是一种常见处理,几乎可以在任何代码库中找到:


START_TIME = getCurrentTime()
executeAction()
ELAPSED_TIME = getCurrentTime() - START_TIME


Java中的运行时间


Java提供了两个时间测量基础调用:System.currentTimeMillis()和System.nanoTime()。这两个调用有以下几个区别。


1.计时起点的稳定性


System.currentTimeMillis()返回自UTC时间1970年1月1日(Unix纪元开始)开始经过的毫秒数。另一个调用,System.nanoTime()返回自某一固定但任意的时间点开始经过的纳秒数。


很明显,currentTimeMillis()的测量粒度为1毫秒。因此测量时间不能短于1毫秒。currentTimeMillis()用UTC时间1970年1月1日作为参照点,既有优点也有缺点。


有什么优点?可以在两个不同JVM上调用currentTimeMillis(),比较返回值。


有哪些缺点?如果计算机没有进行时间同步,那么比较的结果没有意义。服务集群中的时钟通常无法做到完全同步,总会有一些偏差。如果是比较两个不同系统产生的日志文件,时间戳不完全同步尚且可以接受。但是,有时候这种偏差可能会导致灾难性后果,例如分布式系统中的冲突解决。


2.时钟的单调性


另一个问题,不能保证返回值单调递增。这是什么含义?连续两次调用currentTimeMillis(),第二次调用的返回值可能小于第一次。这种结果违反直觉,而且可能导致荒谬的结果,比如经过的时间为负数。很明显,要计算程序内部运行经过的时间currentTimeMillis()不是一个好的选项。那么,用nanoTime()怎么样?

System.nanoTime()没有用Unix纪元作为参考点,而是使用过去某个未指定时间点。该时间点仅在一次JVM运行期间保持不变,仅此而已。因此,即使比较同一台计算机上两个不同JVM的nanoTime()返回值也毫无意义,更不用说比较不同计算机上的调用结果。参考时间点通常与上一次计算机启动有关,不能依赖这种实现。这种做法的好处是,即使计算机的时钟时间由于某种原因倒退,也不会对nanoTime()产生任何影响。因此,nanoTime()是一个很棒的工具,可以测量单个JVM中两个事件之间经过的时间,但是不能用来比较不同JVM中的时间。


Java实现


接下来会探讨currentTimeMillis()和nanoTime()在Java中的实现机制。这里使用最新的OpenJDK 14源代码。System.currentTimeMillis()是一个本地方法,因此Java IDE不会告诉我们具体实现。这段本地代码看起来稍微好一点:


JVM_LEAF(jlong, JVM_CurrentTimeMillis(JNIEnv *env, jclass ignored))
 JVMWrapper("JVM_CurrentTimeMillis");
 return os::javaTimeMillis();
JVM_END


可以看到,这里会根据不同的操作系统委派不同的实现。下面是Linux上的实现:


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);
}


这段代码委托给一个Posix函数gettimeofday()。该函数返回一个简单的结构:


struct timeval {
 time_t tv_sec; /* seconds */
 suseconds_t tv_usec; /* microseconds */
};


结构体中包含自Unix纪元开始经过的秒数,以及最后的微秒数。currentTimeMillis()返回的是自Unix纪元以来经过的毫秒数,因此必须进行简单的转换:jlong(time.tv_sec) * 1000 + jlong(time.tv_usec / 1000)


gettimeofday()函数由glibc实现,最终调用Linux内核。稍后会进行更深入了解。


让我们看看nanoTime()如何实现:事实证明没有太大区别,System.nanoTime()也是一个本机方法:public static native long nanoTime();和jvm.cpp会交给操作系统实现:


JVM_LEAF(jlong, JVM_NanoTime(JNIEnv *env, jclass ignored))
 JVMWrapper("JVM_NanoTime");
 return os::javaTimeNanos();
JVM_END


Linux中的javaTimeNanos()实现非常有趣:


jlong os::javaTimeNanos() {
 if (os::supports_monotonic_clock()) {
   struct timespec tp;
   int status = os::Posix::clock_gettime(CLOCK_MONOTONIC, &tp);
   assert(status == 0, "gettime error");
   jlong result = jlong(tp.tv_sec) * (1000 * 1000 * 1000) + jlong(tp.tv_nsec);
   return result;
 } else {
   timeval time;
   int status = gettimeofday(&time, NULL);
   assert(status != -1, "linux error");
   jlong usecs = jlong(time.tv_sec) * (1000 * 1000) + jlong(time.tv_usec);
   return 1000 * usecs;
 }
}


实现包含2个分支:如果操作系统支持,那么使用单调时钟;否则还是委托给gettimeofday()。Gettimeofday()与之前System.currentTimeMillis()中用的同一个Posix调用。显然,由于nanoTime()的粒度更细,因此转换实现看起来有些不同,但使用的是同一个Posix调用!这意味着,在某些情况下System.nanoTime()使用Unix纪元作为参考点,因此也可以追溯过去!换句话说:不能保证单调性!


好消息是,据我所知所有现代Linux发行版都支持单调时钟。我认为这个分支是为了兼容早期kernel/glibc版本。假如你对HotSpot如何检测操作系统支持单调时钟感兴趣,请参阅这段代码。对大多数人而言,重要的要知道OpenJDK实际总是调用的是Posix函数clock_gettime(),该函数在glibc中实现,glibc会委托给Linux内核调用。


基准测试I、本地笔记本


现在,我们对nanoTime()和currentTimeMillis()的实现有了一个直观的认识。让我们看看它们速度是快是慢。下面是一个简单的JMH基准测试:


@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public class Bench {

 @Benchmark
 public long nano() {
   return System.nanoTime();
 }

 @Benchmark
 public long millis() {
   return System.currentTimeMillis();
 }
}


我的笔记本装的是Ubuntu 19.10,运行上面的基准测试结果如下:



System.currentTimeMillis()每次调用大约需要29纳秒,System.nanoTime()大约每次需要25纳秒。结果中规中矩。这也意味着,使用System.nano()测试短于几十纳秒的调用是不明智的。因为测量本身的开销可能大于所要测量的时间段。此外,还要避免在密集的循环中使用nanoTime(),因为这么做会使得延迟迅速增加。另一方面,使用nanoTime()计算远程服务器的响应时间或者开销很大的计算过程很合适。


基准测试II、AWS


虽然在笔记本上运行基准测试很方便,但并不实用。除非把笔记本贡献出来,作为应用的生产环境。让我们在AWS EC2中运行相同的基准测试。


启动一台安装了Ubuntu 16.04 LTS的c5.xlarge机器,并使用SDKMAN安装AdoptOpenJDK构建的Java 13:


$ sudo apt install zip unzip
$ curl -s "https://get.sdkman.io" | bash
# 我直到使用Pipe把curl结果输出到shell不酷。但是我很懒。
$ source "/home/ubuntu/.sdkman/bin/sdkman-init.sh"
$ sdk install java 13.0.1.hs-adpt


$ java -version
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment AdoptOpenJDK (build 13.0.1+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 13.0.1+9, mixed mode, sharing)
ubuntu@ip-10-0-0-133:~$


运行结果如下:


图片


与笔记本上的运行结果几乎一样,还不错。现在,试一下c3.large实例。虽然比较老,但是现在仍然经常使用:


图片


结果看起来很糟糕!尽管c3.large实例有点老,预期的运行结果会有所下降,但这也差太多了!currentTimeMillis()和nanoTime()结果都慢了一个数量级。360纳秒一开始听起来感觉还不错,但要考虑这只是测量一次需要的时间,而实际要调用两次。因此,实际每次测量耗费大约0.7微秒。如果有10个探针测量不同的执行阶段,那么实际需要7微秒。详细分析:40gbit网卡的往返大约需要10微秒。这意味着,如果向热点路径增加一堆探针可能会带来非常大的延迟!


关于内核的调查


为什么C3实例比笔记本电脑或者C5实例慢得多?事实证明,这与Linux时钟源有关,更主要的与glibc-kernel接口有关。我们已经知道,每次调用nanoTime()或者currentTimeMillis()OpenJDK都会调用本机代码,本机代码会调用glibc,后者会调用Linux内核。


最有趣的部分是glibc-Linux内核转换:通常,当进程调用Linux内核函数(也称为syscall)时,涉及从用户模式切换到内核模式然后返回。这个转换是一个开销相对很高的操作,涉及许多步骤:


  • 把CPU寄存器存储在内核堆栈中

  • 运行内核代码调用函数

  • 把运行结果从内核空间复制到用户空间

  • 从内核堆栈恢复CPU寄存器

  • 跳转到用户代码


这些操作的开销通常很大。而且伴随着旁道***和相关保障措施的出现,开销越来越大。


对性能敏感的应用程序通常会尽量避免从用户态切换到内核态。Linux内核本身为一些频繁执行的系统调用提供了快捷方式,称为vDSO — 虚拟动态共享对象。它的本质是导出一些函数,把它们映射到进程的地址空间中。用户进程可以像普通共享库中的普通函数一样调用它们。事实证明,clock_gettime()和gettimeofday()都提供了这种快捷调用。因此,当glibc调clock_gettime()时,实际上不会执行用户态-内核态切换,仅仅是内存地址跳转。


所有这些听起来更像是一个有趣的理论,但并不能解释为什么System.nanoTime()在c3实例上运行这么慢。


实验


这里使用另一个出色的Linux工具监视系统调用次数:perf。最简单的办法,启动基准测试并计算操作系统中的所有系统调用。perf的语法非常简单:


sudo perf stat -e raw_syscalls:sys_enter -I 1000 -a,会计算每秒钟系统调用总数。一个重要的细节:它只统计真正的系统调用,即执行了完整用户模式-内核模式转换过程。vDSO不在统计范围之内。下面是c5实例上运行时的结果:


$ sudo perf stat -e raw_syscalls:sys_enter -I 1000 -a
# time counts unit events
1.000082884 138 raw_syscalls:sys_enter
2.000222087 252 raw_syscalls:sys_enter
3.000343414 127 raw_syscalls:sys_enter
4.000455977 136 raw_syscalls:sys_enter
5.000569565 140 raw_syscalls:sys_enter
6.000678534 136 raw_syscalls:sys_enter


可以看到每秒大约执行了130个系统调用。鉴于我们基准测试的每次循环都小于30纳秒,很明显应用程序应该使用vDSO避开了系统调用。


下面是在c3实例上的运行结果:


$ sudo perf stat -e raw_syscalls:sys_enter -I 1000 -a
time counts unit events
1.000159646 1390979 raw_syscalls:sys_enter
2.000942549 1391734 raw_syscalls:sys_enter
3.001555643 1392785 raw_syscalls:sys_enter
4.002148930 1393389 raw_syscalls:sys_enter
5.002734293 1392383 raw_syscalls:sys_enter
6.003311904 1338051 raw_syscalls:sys_enter


每秒执行超过130万次系统调用!而且nanoTime()和currentTimeMillis()用时翻倍,大约为每次操作700纳秒。这是一个相当有力的证明,每次基准测试循环都会执行一次真实的系统调用!


让我们再启动一个perf命令以收集其他证据。这个命令会计算5秒钟内调用的所有系统调用并按名称分组:


sudo perf stat -e 'syscalls:sys_enter_*' -a sleep 5


在c5实例上运行时没有任何异常。但是在c3实例上运行时,会看到下面的结果:


15695416 syscalls:sys_enter_gettimeofday (99.98%)


这就是确凿的证据!这个证据有力地证明了,在c3实例上运行基准测试时,会进行真正的gettimeofday()系统调用!为什么?


这是4.4内核(Ubuntu 16.04)的相关说明:

notrace int __vdso_gettimeofday(struct timeval *tv, struct timezone *tz)
{
 if (likely(tv != NULL)) {
   if (unlikely(do_realtime((struct timespec *)tv) == VCLOCK_NONE))
     return vdso_fallback_gtod(tv, tz);
   tv->tv_usec /= 1000;
 }
 if (unlikely(tz != NULL)) {
   tz->tz_minuteswest = gtod->tz_minuteswest;
   tz->tz_dsttime = gtod->tz_dsttime;
 }

 return 0;
}


这是Java调用System.currentTimeMillis()时,由glibc调用的用户态内存映射函数。它会调用do_realtime(),并使用当前时间填充struct tv返回。重要的是,所有这些操作均在用户模式下执行,不会产生系统调用。好吧,do_realtime()返回VCLOCK_NONE时除外。在这种情况下,会调用vdso_fallback_gtod()执行系统调用。


为什么c3会fallback执行系统调用而c5不会?这与虚拟化技术的变化有关!AWS从一开始就使用Xen虚拟化。大约2年前,AWS宣布从Xen转为KVM虚拟化。c3实例使用Xen虚拟化,较新的c5实例则使用KVM。对我们而言重要的是要知道,每种技术使用了不同的Linux Clock实现。在/sys/devices/system/clocksource/clocksource0/current_clocksource中可以看到Linux当前时钟。


下面是c3的结果:


$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
Xen


这是c5的结果:


$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
kvm-clock


事实证明,kvm-clock实现中会设置vclock_mode为VCLOCK_PVCLOCK,这样不会fallback到较慢的分支。Xen时钟源没有设置mode,而是保持了VCLOCK_NONE默认值。这样会跳转到vdso_fallback_gtod()函数,最后执行真正的系统调用!


#define VCLOCK_NONE 0/* No vDSO clock available.*/
#define VCLOCK_TSC 1/* vDSO should use vread_tsc.*/
#define VCLOCK_HPET 2/* vDSO should use vread_hpet.*/
#define VCLOCK_PVCLOCK 3/* vDSO should use vread_pvclock.*/

struct arch_clocksource_data {
 int vclock_mode;
};


Linux的优点在于它具有高度的可配置性,并且经常会让我们自取灭亡。可以尝试更改c3上的时钟源并重新运行基准测试。可以执行下面命令查看:


$ cat /sys/devices/system/clocksource/clocksource0/available_clocksource
xen tsc hpet acpi_pm。


TSC是Time Stamp Counter的缩写,是一种非常快速的时间源。对于我们而言最重要的是知道它是一种很好的vDSO实现。把c3实例中的时钟源从Xen切换到TSC:

# echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksource


检查是否完成切换:


$ cat /sys/devices/system/clocksource/clocksource0/current_clocksource
tsc


看起来不错!现在重新运行基准测试:


图片


结果看起来不错!实际上,比使用kvm-clock的c5实例表现更好。每秒系统调用数与c5实例处于同一数量级:


ubuntu@ip-10-0-0-133:~$ sudo perf stat -e raw_syscalls:sys_enter -I 1000 -a
# time counts unit events
1.000172233 144 raw_syscalls:sys_enter
2.000726439 203 raw_syscalls:sys_enter
3.001163704 180 raw_syscalls:sys_enter
4.001595597 177 raw_syscalls:sys_enter
5.002030641 192 raw_syscalls:sys_enter


有些人甚至建议,在使用Xen虚拟化时也建议将时钟源切换为TSC。我对于这种方案可能产生的副作用知之甚少,但是即使是一些大公司甚至在生产环境也这么干。显然,这并不证明这种方案是安全的,但可以说它对某些情况有效。


总结


通过本文可以看到底层的实现细节如何对普通Java调用性能产生重大影响。这不仅是基准测试中看到的理论,实际系统也会受到影响。可以直接在Linux内核源代码树中查看更多vDSO相关信息。


没有杰出的同事帮助,单我一个人无法完成本文的工作Hazelcast。这是一支世界一流团队,我从他们那里学到了很多东西!感谢Brendan Gregg收集的,perf技巧。我的记性一直很差,Brendan提供了一份很棒cheatsheet。


标签:调用,Java,currentTimeMillis,sys,raw,API,内核,syscalls,nanoTime
来源: https://blog.51cto.com/u_15127686/2832586

本站声明: 1. iCode9 技术分享网(下文简称本站)提供的所有内容,仅供技术学习、探讨和分享;
2. 关于本站的所有留言、评论、转载及引用,纯属内容发起人的个人观点,与本站观点和立场无关;
3. 关于本站的所有言论和文字,纯属内容发起人的个人观点,与本站观点和立场无关;
4. 本站文章均是网友提供,不完全保证技术分享内容的完整性、准确性、时效性、风险性和版权归属;如您发现该文章侵犯了您的权益,可联系我们第一时间进行删除;
5. 本站为非盈利性的个人网站,所有内容不会用来进行牟利,也不会利用任何形式的广告来间接获益,纯粹是为了广大技术爱好者提供技术内容和技术思想的分享性交流网站。

专注分享技术,共同学习,共同进步。侵权联系[81616952@qq.com]

Copyright (C)ICode9.com, All Rights Reserved.

ICode9版权所有