在分析应用服务性能时，我们常常会查看垃圾收集日志文件（gc.log）来追踪gc活动的轨迹。在这些日志中，我们经常会看到每个gc事件的三种时间类型："user"、"sys"和"real"。它们分别代表什么？具有哪些象征性意义？本文将结合实际经验简要解析这些时间类型，希望对大家在gc log分析和问题定位有所帮助。
以下是基于G1垃圾回收策略的GC Log内容，因篇幅有限，仅显示部分内容：
[administrator@JavaLangOutOfMemory luga %]less echo-admin-gc.log ... ...2015-09-14T12:32:24.398-0700: 0.356: [GC pause (G1 Evacuation Pause) (young), 0.0215287 secs] [Parallel Time: 20.0 ms, GC Workers: 8] [GC Worker Start (ms): Min: 355.9, Avg: 356.3, Max: 358.4, Diff: 2.4] [Ext Root Scanning (ms): Min: 0.0, Avg: 6.4, Max: 16.7, Diff: 16.7, Sum: 51.4] [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.5, Diff: 2.5, Sum: 8.2] [Processed Buffers: Min: 0, Avg: 1.1, Max: 5, Diff: 5, Sum: 9] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [Object Copy (ms): Min: 2.9, Avg: 11.9, Max: 17.5, Diff: 14.6, Sum: 95.3] [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.9] [Termination Attempts: Min: 1, Avg: 2.5, Max: 5, Diff: 4, Sum: 20] [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5] [GC Worker Total (ms): Min: 17.5, Avg: 19.6, Max: 19.9, Diff: 2.4, Sum: 156.5] [GC Worker End (ms): Min: 375.8, Avg: 375.9, Max: 375.9, Diff: 0.1] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.5 ms] [Other: 1.0 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.4 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.4 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 12.0M(12.0M)->0.0B(14.0M) Survivors: 0.0B->2048.0K Heap: 12.6M(252.0M)->7848.3K(252.0M)] [Times: user=0.08 sys=0.00, real=0.02 secs] 2015-09-14T12:32:24.932-0700: 0.889: [GC pause (G1 Evacuation Pause) (young), 0.0469650 secs]
从上述输出文件中，我们可以看到在年轻代GC事件后面有三种不同时间的详细打印：
[Times: user=0.08 sys=0.00, real=0.02 secs]。关于如何在应用程序运行过程中输出GC Log，可参考之前的文章：Java虚拟机三件套解析。
当我们拿到这份GC日志文件，常常会遇到许多问题：每个GC事件花费的时间都会在GC日志中报告。在每个GC事件中，都有“用户”、“系统”和“实时”时间。它们代表什么意思？它们之间有什么本质区别？我们如何打印这些时间，以及在什么时间监控？
立即学习“Java免费学习笔记（深入）”；
在我们了解GC时间之前，先花几分钟了解Linux/Unix命令的“时间”。具体操作如下：
[administrator@JavaLangOutOfMemory ~ %] time lsDesktop Movies activemq gateway lugaDocuments Music cpu go monitoring-micrometerDownloads Pictures curl-format.txt goPro nacos-dockerIdeaProjects Public deploy-demo.yaml java openshiftLibrary SpringCloud2.x docker k8sreal 0m0.003suser 0m0.000ssys 0m0.001s
通过time ls命令，我们看到这样的输出：
time ls命令首先显示ls命令的执行输出，其中列出了当前目录中的所有目录/文件：
接下来，我们看到执行ls所花费的时间，即：“真实”、“用户”、“系统”时间。这是我们在GC日志中看到的相同数据。
下面是在每种情况下StackOverflow中提供的一个很好的定义：
Real（实际时间） 是挂钟时间——从事件开始到结束的时间。这是所有经过的时间，包括其他进程使用的时间片以及该进程花费的时间被阻塞（例如，如果它正在等待I/O完成）。
User（用户时间） 是进程中用户模式代码（内核外部）所花费的CPU时间片。这只是执行过程中使用的实际CPU时间。该进程花费的其他进程和时间不计入该数字。
Sys（系统时间） 是进程中在内核中花费的CPU时间量。这意味着在内核内部执行系统调用所花费的CPU时间，而不是库代码仍在用户空间中运行。就像“用户”一样，这只是进程使用的CPU时间。
User + Sys将告诉我们：我们的进程使用了多少实际CPU时间。请注意，这涉及所有CPU，因此，如果该进程具有多个线程，则有可能超过Real Times的挂钟时间。
刚才我们讲到了Linux/Unix时间概念，现在我们着重看下Java GC Times。这与GC日志记录中应用的概念相同。
在Java GC Times概念中，每个GC事件花费的时间都会在GC日志中报告。在每个GC事件中，都有“user”、“sys”和“real”。这些时间是什么意思？它们之间有什么区别？
Real（实际时间） 指GC事件的总经过时间。这基本上是您在时钟中看到的时间。
User（用户时间） 指用户模式代码（内核外部）所花费的CPU时间。
Sys（系统时间） 指内核中花费的CPU时间。这意味着在内核内部执行系统调用所花费的CPU时间，而不是库代码仍在用户空间中运行。
让我们看几个简单示例，以便更好地理解这个概念。
示例1：
[Times: user=12.93 sys=2.01, real=1.03 secs]
在这个示例中：“user” + “sys”远大于“real”。这是因为此日志时间是从JVM收集的，在JVM中，多核/多处理器服务器上配置了多个GC线程。当多个线程并行执行GC时，工作负载将在这些线程之间共享。因此，实际时钟时间（“real”）比CPU总时间（“user” + “sys”）少得多。
示例2：
[Times: user=0.12 sys=0.00, real=0.12 secs]
上面是从串行垃圾收集器收集的GC时间的示例。由于串行垃圾收集器始终仅使用单个线程，因此实时等于用户和系统时间的总和。
在实际的业务场景中，考虑性能优化时，我们主要偏向在为客户优化响应时间。客户不在乎我们使用多少GC线程或拥有多少处理器。因此，我们需要重点关注“real”时间，但这并不意味着“sys”或“user”时间并不重要。它们对于查看是否要增加GC线程数或CPU处理器数以减少GC暂停时间也很重要。
在正常的（所有）GC事件中，Real Time将小于（User+Sys）Time。这是因为多个GC线程同时工作以分担工作量，因此实时时间将少于用户+系统时间。假设（User+Sys）Time为2秒。如果5个GC线程同时工作，则实时应该在400毫秒左右（2秒/5个GC线程）附近。但是在某些情况下，我们可能会看到Real Time >（User+Sys）Time。
我们看一下示例：
[Times: user=0.80 sys=0.05, real=20.37 secs]
如果我们在GC日志中发现多次出现此情况（Real Time明显大于User Time与Sys Time之和），则可能表明存在以下问题之一：
- I/O繁忙
- CPU不足
下面我们针对出现的性能问题进行分析：
I/O繁忙
当服务器上发生大量I/O活动（即网络/磁盘访问/用户交互）时，实时性往往会在很大程度上飙升。作为GC日志记录的一部分，我们的应用程序进行磁盘访问。如果服务器上的I/O活动繁重，则GC事件可能会搁浅，从而导致实时峰值。
注意：即使我们的应用程序没有引起繁重的I/O活动，服务器上的其他进程也可能导致繁重的I/O活动，从而导致较高的实时性。
我们可以在Linux/Unix中使用sar（系统活动报告）监视服务器上的I/O活动。具体为：
[administrator@JavaLangOutOfMemory ~ %]sar -d -p 1
上面的命令每1秒报告一次对设备的读取/秒和写入/秒。有关“sar”命令的更多详细信息，请参官网教程。
如果我们发现服务器上的I/O活动很高，则可以执行以下任一操作来解决此问题：
- 如果我们的应用程序引起了较高的I/O活动，请优化应用程序的I/O活动。
- 消除导致服务器上大量I/O活动的进程。
- 将我们的应用程序移到I/O活动较少的其他服务器上。
CPU不足
如果我们的服务器上正在运行多个进程，并且我们的应用程序没有足够的CPU周期来运行，它将开始等待。当应用程序开始等待时，实时将大大高于用户+系统时间。
我们可以使用“top”之类的命令或监视工具（nagios，newRelic，AppDynamics…）来观察服务器上的CPU利用率。如果我们发现CPU使用率很高，并且进程没有足够的周期来运行，则可以执行以下一项操作来解决此问题：
- 减少服务器上正在运行的进程数，以便我们的应用程序有运行的资源空间。
- 增加CPU容量，将应用服务移至具有更多CPU核心的更大实例类型。
- 将我们的应用程序移到具有足够CPU容量的新服务器上。
基于以上的解析过程，希望本文对大家有所帮助，使得我们能够熟悉GC Log里面的奥秘，以便我们的应用程序在运行过程中以获得最佳性能表现。
