在 GC 日志文件中,每个 GC 事件有三种类型的时间:
例如:
[Times: user=11.53 sys=1.38, real=1.03 secs].
在我们开始分析 GC 日志的时候,会遇到两个问题:
1、user
、sys
和 real
三者之间有什么不同?
2、我们该使用哪一个时间来分析日志?
在弄清楚 GC 时间之前,我们先花几分钟来看看 Unix 的 time
命令。以下是使用该命令的一个示例:
time ls
命令执行之后,你会看到控制台输出这些信息:
在上图中,time ls
命令首先输出 ls
命令的执行结果,列出了当前目录下的所有目录/文件:
紧接着我们会看到 ls
命令执行的时间:
注意这里显示出了 real
、user
和 sys
三个时间,这些时间与我们在 GC 日志里看到的大致相同。现在我们来看看 StackOverflow 上提供的关于这些时间的解释:
Real is wall clock time – time from start to finish of the call. This is all elapsed time including time slices used by other processes and time the process spends blocked (for example if it is waiting for I/O to complete).
User is the amount of CPU time spent in user-mode code (outside the kernel) within the process. This is only actual CPU time used in executing the process. Other processes and time the process spends blocked do not count towards this figure.
Sys is the amount of CPU time spent in the kernel within the process. This means executing CPU time spent in system calls within the kernel, as opposed to library code, which is still running in user-space. Like ‘user’, this is only CPU time used by the process.
通过上面的这段英文我们可以知道这三个时间的概念:
user + sys 时间告诉我们程序执行实际使用的 CPU 时间。注意这里指所有的 CPU,因此如果在进程里有多个线程的话,这个时间可能会超过 real 所表示的时钟时间。
上面我们解释了三个时间的概念,接下来我们用一些例子来更好地说明这些概念:
例1:
[Times: user=11.53 sys=1.38, real=1.03 secs]
在这个例子中,user
+ sys
时间的和比 real
时间要大,这主要是因为日志时间是从 JVM 中获得的,而这个 JVM 在多核的处理器上被配置了多个 GC 线程,由于多个线程并行地执行 GC,因此整个 GC 工作被这些线程共享,最终导致实际的时钟时间(real)小于总的 CPU 时间(user + sys)。
例2:
[Times: user=0.09 sys=0.00, real=0.09 secs]
上面的例子中的 GC 时间是从 Serial 垃圾收集器 (串行垃圾收集器)中获得的。由于 Serial 垃圾收集器是使用单线程进行垃圾收集的,因此 real
时间等于 user
和 sys
时间之和。
在做性能优化时,我们一般采用 real
时间来优化程序。因为最终用户只关心点击页面发出请求到页面上展示出内容所花的时间,也就是响应时间,而不关心你到底使用了多少个 GC 线程或者处理器。但并不是说 sys
和 user
两个时间不重要,当我们想通过增加 GC 线程或者 CPU 数量来减少 GC 停顿时间时,可以参考这两个时间。
参考资料: