Java GC Log Time解析

在分析应用服务性能时，我们常常会查看垃圾收集日志文件（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之和），则可能表明存在以下问题之一：

1. I/O繁忙
2. 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活动很高，则可以执行以下任一操作来解决此问题：

1. 如果我们的应用程序引起了较高的I/O活动，请优化应用程序的I/O活动。
2. 消除导致服务器上大量I/O活动的进程。
3. 将我们的应用程序移到I/O活动较少的其他服务器上。

CPU不足

如果我们的服务器上正在运行多个进程，并且我们的应用程序没有足够的CPU周期来运行，它将开始等待。当应用程序开始等待时，实时将大大高于用户+系统时间。

我们可以使用“top”之类的命令或监视工具（nagios，newRelic，AppDynamics…）来观察服务器上的CPU利用率。如果我们发现CPU使用率很高，并且进程没有足够的周期来运行，则可以执行以下一项操作来解决此问题：

1. 减少服务器上正在运行的进程数，以便我们的应用程序有运行的资源空间。
2. 增加CPU容量，将应用服务移至具有更多CPU核心的更大实例类型。
3. 将我们的应用程序移到具有足够CPU容量的新服务器上。

基于以上的解析过程，希望本文对大家有所帮助，使得我们能够熟悉GC Log里面的奥秘，以便我们的应用程序在运行过程中以获得最佳性能表现。

以上就是Java GC Log Time解析的详细内容，更多请关注php中文网其它相关文章！