Java的GC调优介绍

介绍Java的GC调优方法

Posted by qin4zhang on September 8, 2019

注意

想法及时记录,实现可以待做。

GC调优-基础篇

优化垃圾收集与任何其他性能优化活动没有什么不同。很容易陷入随机调整200个与gc相关的JVM参数中的一个或开始更改应用程序代码的随机部分的陷阱。相反,遵循一个简单的过程将确保你正在朝着正确的目标前进,同时保持进度的透明度:

  1. 陈述优化目标
  2. 运行测试
  3. 测量结果
  4. 将结果与目标进行比较
  5. 如果目标没有达到,则进行更改并返回运行测试

因此,作为第一步,我们需要在垃圾收集方面设置明确的性能目标。目标分为三类,这三类对所有性能监视和管理主题都是通用的:

  • 延迟
  • 吞吐量
  • 容量

在一般地解释了这些概念之后,我们将演示如何在垃圾收集上下文中应用这些目标。如果你已经熟悉延迟、吞吐量和容量的概念,那么可以跳过。

核心概念

让我们通过观察工厂中的装配线来从一个制造业的例子开始。这条生产线是用现成的零件组装自行车。自行车按顺序在这条生产线上生产。

在监测这条线的运行时,我们测量从框架进入这条线到组装好的自行车在另一端离开这条线需要4个小时来完成一辆自行车。

装配

继续观察,我们还可以看到,每天24小时,每分钟组装一辆自行车。简化示例,忽略维护窗口,我们可以预测,在任何给定的小时,这样一条装配线组装60辆自行车。

有了这两种测量方法,我们现在拥有了关于装配线当前性能的关键信息,包括延迟和吞吐量:

  • 装配线的延迟:4小时
  • 装配线的吞吐量:60辆/小时

请注意,延迟是以适合当前任务的时间单位来衡量的——从纳秒到千年都是不错的选择。系统的吞吐量是以每一时间单位完成的操作来衡量的。

操作可以是与特定系统相关的任何东西。在这个例子中,选择的时间单位是小时,操作是装配好的自行车。

在配置了延迟和吞吐量的定义之后,让我们在同一个工厂中执行性能调优练习。自行车需求稳定了一段时间,装配线持续生产自行车,延迟4小时,吞吐量为60辆/小时,持续了几个月。

现在让我们想象这样一种情况:销售团队取得了成功,自行车的需求突然翻了一番。与通常的60*24 = 1440辆/天相比,客户的需求增加了一倍。工厂的业绩不再令人满意了,需要做点什么了。

工厂经理似乎正确地得出结论,系统的延迟不是一个问题——相反,他应该关注每天生产的自行车总数。得出这个结论并假设他有充足的资金,假设的经理将立即采取必要的步骤,通过增加产能来提高吞吐量。

因此,我们现在在同一家工厂里观察的不是一条而是两条完全相同的装配线。这两条装配线每天每分钟都在组装同一辆自行车。

通过这样做,我们想象中的工厂每天生产的自行车数量增加了一倍。这家工厂现在每天能运送2880辆自行车,而不是1440辆。值得注意的是,我们并没有将完成一辆自行车的时间缩短哪怕一毫秒—完成一辆自行车仍然需要4个小时。

组装自行车

在上面的示例中,执行了一个性能优化任务,同时影响了吞吐量和容量。在任何好的例子中,我们都是从测量系统当前的性能开始,然后设置一个新的目标,并只在满足目标所需的方面对系统进行优化。

在这个例子中,我们做了一个重要的决定——重点是提高吞吐量,而不是减少延迟。在增加吞吐量的同时,我们还需要增加系统的容量。

我们现在需要两条装配线来生产所需的数量,而不是一条装配线。因此,在这种情况下,增加的吞吐量不是空闲的,解决方案需要扩大规模,以满足增加的吞吐量需求。

对于手头的性能问题,还应该考虑一个重要的替代方案。看似无关的系统延迟实际上隐藏了问题的不同解决方案。如果装配线的延迟可以从1分钟减少到30秒,那么在没有任何额外容量的情况下,也可以突然实现相同的吞吐量增加。

在这种情况下,减少延迟是否可行或经济都无关紧要。重要的是一个非常类似于软件工程的概念——你几乎总是可以在性能问题的两个解决方案中进行选择。你可以使用更多的硬件来解决问题,也可以花时间改进性能较差的代码。

Latency

GC的延迟目标必须从一般的延迟需求中派生出来。一般的延迟需求通常以类似如下的形式表示:

  • 所有用户事务必须在10秒内响应
  • 90%的发票付款必须在3秒内完成
  • 推荐产品必须在少于100毫秒的时间内呈现到购买屏幕上

当面临与上述类似的性能目标时,我们需要确保事务期间GC暂停的持续时间不会过多地违反需求。“太多”是特定于应用程序的,需要考虑导致延迟的其他因素,包括到外部数据源的往返、锁争用问题和其中的其他安全点。

让我们假设我们的性能需求表明,应用程序90%的事务需要在1,000毫秒内完成,并且没有事务可以超过10,000毫秒。

对于这些一般的延迟需求,让我们再次假设GC暂停的贡献不超过10%。由此,我们可以得出结论,90%的GC暂停必须在100毫秒内完成,而且没有GC暂停可以超过1,000毫秒。为了简单起见,让我们在本例中忽略同一事务中可能发生的多个暂停。

将需求形式化之后,下一步是度量暂停持续时间。有许多用于该任务的工具,在工具一章中将有更详细的介绍,但在本节中,我们将使用GC日志,即GC暂停期间的日志。

所需的信息存在于不同的日志片段中,所以让我们看看日期/时间数据的哪些部分是实际相关的,使用以下示例:

2015-06-04T13:34:16.974-0200: 2.578: [Full GC (Ergonomics) [PSYoungGen: 93677K->70109K(254976K)] [ParOldGen: 499597K->511230K(761856K)] 593275K->581339K(1016832K), [Metaspace: 2936K->2936K(1056768K)], 0.0713174 secs] [Times: user=0.21 sys=0.02, real=0.07 secs

上面的示例表示在2015年6月4日13:34:16触发的单个GC暂停,此时JVM启动后仅2578毫秒。

该事件将应用程序线程停止0.0713174秒。尽管在多核上花费了210毫秒的CPU时间,但对我们来说重要的数据是应用程序线程的总停止时间。

在本例中,在多核机器上使用并行GC的情况下,这相当于70毫秒多一点。因此,这个特定的GC暂停大大低于所需的100 ms阈值,并满足了这两个要求。

Throughput

吞吐量需求与延迟需求不同。吞吐量需求与延迟的唯一相似之处是,这些需求同样需要从通用吞吐量需求派生出来。吞吐量的一般要求类似如下:

  • 解决方案必须能够处理1,000,000张发票/天
  • 该解决方案必须支持1,000个经过身份验证的用户,每个用户每5到10秒调用函数A、B或C中的一个
  • 所有客户的每周统计必须在每周日晚上12点到早上6点之间,不超过6个小时内完成

因此,吞吐量需求指定系统在给定的时间单位内必须处理多少操作,而不是为单个操作设置需求。

与延迟需求类似,GC调优部分现在需要确定在测量的时间内可以花在GC上的总时间。对于特定的系统来说,多少是可以容忍的,这也是与应用程序有关的,但作为经验法则,任何超过10%的都是可疑的。

现在让我们假设手头的需求预见到系统每分钟处理1,000个事务。我们还假设每分钟GC暂停的总持续时间不能超过6秒(或10%)。

将需求形式化之后,下一步将是获取我们需要的信息。示例中使用的源仍然是GC日志,从中我们可以得到类似如下的信息:

2015-06-04T13:34:16.974-0200: 2.578: [Full GC (Ergonomics) [PSYoungGen: 93677K->70109K(254976K)] [ParOldGen: 499597K->511230K(761856K)] 593275K->581339K(1016832K), [Metaspace: 2936K->2936K(1056768K)], 0.0713174 secs] [Times: user=0.21 sys=0.02, real=0.07 secs

这一次,我们感兴趣的是用户和系统时间,而不是实时。在本例中,我们应该关注23毫秒(用户和系统时间为21 + 2毫秒),在此期间,特定的GC暂停使cpu繁忙。更重要的是,该系统是在多核机器上运行的,转换为实际的世界停止暂停0.0713174秒,这是将在以下计算中使用的数字。

从整个测试期间的GC日志中提取类似于上述的信息,剩下要做的就是验证每分钟停止世界暂停的总持续时间。如果暂停的总持续时间不超过6000毫秒或在这些1分钟周期中的任何一个周期中不超过6秒,那么我们就满足了要求。

Capacity

容量需求对能够满足吞吐量和延迟目标的环境施加了额外的限制。这些需求可以用计算资源或现金来表示。例如,描述这些要求的方式可以采取以下形式:

  • 要求系统部署在Android设备上,且Android设备的内存小于512mb
  • 统必须部署在Amazon EC2上。所需的最大实例大小不能超过配置c3。xlarge (8g, 4核)
  • Amazon EC2为运行该系统开出的每月发票不能超过12,000美元

因此,在满足延迟和吞吐量需求时,必须考虑容量。有了无限的计算能力,可以满足任何类型的延迟和吞吐量目标,但在现实世界中,预算和其他约束倾向于对可使用的资源设置限制。

示例

现在我们已经介绍了性能调优的三个方面,我们可以开始研究在实践中设置和实现GC性能目标。

为此,让我们看一个示例代码:

//imports skipped for brevity
public class Producer implements Runnable {

  private static ScheduledExecutorService executorService = Executors.newScheduledThreadPool(2);

  private Deque<byte[]> deque;
  private int objectSize;
  private int queueSize;

  public Producer(int objectSize, int ttl) {
    this.deque = new ArrayDeque<byte[]>();
    this.objectSize = objectSize;
    this.queueSize = ttl * 1000;
  }

  @Override
  public void run() {
    for (int i = 0; i < 100; i++) { deque.add(new byte[objectSize]); if (deque.size() > queueSize) {
        deque.poll();
      }
    }
  }

  public static void main(String[] args) throws InterruptedException {
    executorService.scheduleAtFixedRate(new Producer(200 * 1024 * 1024 / 1000, 5), 0, 100, TimeUnit.MILLISECONDS);
    executorService.scheduleAtFixedRate(new Producer(50 * 1024 * 1024 / 1000, 120), 0, 100, TimeUnit.MILLISECONDS);
    TimeUnit.MINUTES.sleep(10);
    executorService.shutdownNow();
  }
}

代码每100毫秒提交两个作业运行。每个作业都模拟具有特定生命周期的对象:它创建对象,让它们在预定的时间内离开,然后忘记它们,允许GC回收内存。

在使用以下参数运行示例时,打开GC日志记录:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps

我们可以立即在日志文件中看到GC的影响,类似如下:

2015-06-04T13:34:16.119-0200: 1.723: [GC (Allocation Failure) [PSYoungGen: 114016K->73191K(234496K)] 421540K->421269K(745984K), 0.0858176 secs] [Times: user=0.04 sys=0.06, real=0.09 secs] 
2015-06-04T13:34:16.738-0200: 2.342: [GC (Allocation Failure) [PSYoungGen: 234462K->93677K(254976K)] 582540K->593275K(766464K), 0.2357086 secs] [Times: user=0.11 sys=0.14, real=0.24 secs] 
2015-06-04T13:34:16.974-0200: 2.578: [Full GC (Ergonomics) [PSYoungGen: 93677K->70109K(254976K)] [ParOldGen: 499597K->511230K(761856K)] 593275K->581339K(1016832K), [Metaspace: 2936K->2936K(1056768K)], 0.0713174 secs] [Times: user=0.21 sys=0.02, real=0.07 secs]

根据日志中的信息,我们可以从三个不同的目标着手改善情况:

  1. 确保最坏情况下GC暂停不会超过预定的阈值
  2. 确保应用程序线程停止的总时间不超过预定的阈值
  3. 降低基础设施成本,同时确保我们仍然可以实现合理的延迟和/或吞吐量目标

为此,上面的代码在三个不同的配置上运行了10分钟,提供了下表中总结的三个非常不同的结果:

GC算法 有用功 最长暂停
-Xmx12g -XX:+UseConcMarkSweepGC 89.8% 560 ms
-Xmx12g -XX:+UseParallelGC 91.5% 1,104 ms
-Xmx8g -XX:+UseConcMarkSweepGC 66.3% 1,610 ms

该实验使用不同的GC算法和不同的堆大小运行相同的代码,以衡量关于延迟和吞吐量的垃圾收集暂停的持续时间。实验的细节和结果的解释将在接下来的章节中给出。

请注意,为了使示例尽可能简单,只更改了有限数量的输入参数,例如,实验不会在不同数量的内核或使用不同的堆布局进行测试。

延迟调优

假设我们有一个要求,要求所有作业的处理时间必须小于1,000 ms。知道实际的作业处理只需要100毫秒,我们就可以简化并扣除每个GC暂停的延迟需求。

我们现在的要求是没有GC暂停可以让应用程序线程停止超过900毫秒。回答这个问题很简单,只需要解析GC日志文件并找到每个GC暂停的最大暂停时间。

再次查看测试中使用的三个配置选项,我们可以看到,已经有一种配置符合这个要求。运行代码:

java -Xmx12g -XX:+UseConcMarkSweepGC Producer

导致最大GC暂停时间为560毫秒,这很好地超过了满足延迟需求所设置的900毫秒阈值。如果没有违反吞吐量和容量需求,我们可以得出结论,我们已经完成了GC调优任务,可以完成调优练习。

吞吐量调优

让我们假设我们的吞吐量目标是每小时处理13,000,000个作业。再次使用的配置示例给了我们一个满足需求的配置:

java -Xmx12g -XX:+UseParallelGC Producer

我们可以看到,cpu被GC阻塞的时间占8.5%,剩下的91.5%的计算能力用于有用的工作。为了简单起见,我们将忽略示例中的其他安全点。现在我们必须考虑到:

  1. 单个核在100毫秒内处理一个作业
  2. 因此,在一分钟内,一个核心可以处理60,000个任务
  3. 因此,在一个小时内,单个核心可以处理3.6 M个工作
  4. 我们有四个可用的核心,因此可以在一个小时内处理4 x 3.6 M = 14.4 M的任务

有了这个量的理论处理能力,我们可以做一个简单的计算,并得出结论,在一个小时内,我们在现实中可以处理14.4 M理论最大值的91.5%,导致1317.6万个处理任务/小时,满足我们的要求。

值得注意的是,如果我们同时需要满足前一节中设置的延迟需求,我们将会遇到麻烦,因为这种情况的最坏情况延迟接近前一配置的两倍。这次记录中最长的GC暂停阻塞了应用程序线程1,104毫秒。

容量调优

假设我们必须将解决方案部署到日用品级的硬件上,最多有4个核和10g RAM可用。由此我们可以得出应用程序的最大堆空间不能超过8 GB的容量需求。有了这个需求,我们就需要转向运行测试的第三个配置:

java -Xmx8g -XX:+UseConcMarkSweepGC Producer

但延迟和吞吐量都急剧下降:

  • GC现在阻止cpu做更多有用的工作,因为这种配置只留下66.3%的cpu做有用的工作。因此,这种配置会将吞吐量从最佳情况下的13,176,000个作业/小时降至9,547,200个作业/小时
  • 在最坏的情况下,我们现在面临的延迟不是560毫秒,而是增加了1610毫秒

纵观这三个维度,很明显,你不能仅仅针对“性能”进行优化,而是需要考虑三个不同的维度,测量和调优延迟和吞吐量,并考虑容量约束。

GC调优:工具

在优化JVM以实现更有效的垃圾收集之前,你需要获取有关其当前行为的信息,以了解GC对应用程序的影响以及最终用户对它的看法。有多种方法可以观察GC的工作,在本章中我们将讨论几种不同的可能性。

在观察GC行为时,有JVM运行时提供的原始数据。此外,还可以根据原始数据计算出派生指标。例如,原始数据包括:

  • 当前内存池占用率
  • 内存池的容量
  • 单个GC暂停的持续时间
  • 这些暂停的不同阶段的持续时间

派生的指标包括,例如,应用程序的分配和提升率。本章主要讨论获取原始数据的方法。最重要的派生指标将在下一章中讨论最常见的gc相关性能问题。

JMX API

从正在运行的JVM中获取gc相关信息的最基本方法是通过标准JMX API。这是JVM公开关于JVM运行时状态的内部信息的标准化方法。你可以通过编程方式从运行在同一个JVM中的自己的应用程序访问这个API,或者使用JMX客户机。

最流行的两个JMX客户端是JConsole和JVisualVM(安装了相应的插件)。这两种工具都是标准JDK发行版的一部分,因此很容易上手。如果你运行的是JDK 7u40或更高版本,则还可以使用第三个绑定到JDK中的工具,即Java Mission Control。

所有JMX客户机都作为连接到目标JVM的独立应用程序运行。目标JVM可以是客户机本地的(如果运行在同一台机器上),也可以是远程的。

对于来自客户机的远程连接,JVM必须显式地允许远程JMX连接。这可以通过将特定的系统属性设置到希望启用JMX RMI连接的端口来实现:

java -Dcom.sun.management.jmxremote.port=5432 com.yourcompanyYourApp

在上面的示例中,JVM为JMX连接打开端口5432。

将你的JMX客户机连接到感兴趣的JVM并导航到mbean列表之后,在节点“java.lang/GarbageCollector”下选择mbean。下面两个屏幕截图分别展示了JVisualVM和Java Mission Control的GC行为信息:

JVisualVM

JMC

如上面的截图所示,有两个垃圾收集器。其中一个收集器负责清理年轻代,另一个负责清理老年代。这些元素的名称对应于所使用的垃圾收集器的名称。

在上面的截图中,我们可以看到特定的JVM在年轻代中使用ParallelNew,在老代中使用CMS。

对于每个收集器,JMX API公开以下信息:

  • CollectionCount——收集器在JVM中运行的总次数,
  • CollectionTime—收集器运行时间的累计持续时间。时间是所有GC事件的时钟时间之和,
  • LastGcInfo——关于上次垃圾收集事件的详细信息。该信息包含该事件的持续时间、事件的开始和结束时间,以及上次收集前后不同内存池的使用情况,
  • MemoryPoolNames——该收集器管理的内存池的名称,
  • Name—垃圾回收器的名称
  • ObjectName——这个MBean的名称,由JMX规范规定,
  • Valid—显示此收集器在此JVM中是否有效。我个人在这里只看到了“true”

根据我的经验,这些信息不足以对垃圾收集器的效率做出任何结论。只有在你愿意构建自定义软件以获得关于垃圾收集事件的JMX通知时,它才会发挥作用。这种方法很少被使用,我们将在下一节中看到,这将提供更好的方法来深入了解垃圾收集活动。

JVisualVM

JVisualVM通过一个名为“VisualGC”的独立插件为基本的JMX客户端功能添加了额外的信息。它提供了GC事件和JVM中不同内存区域占用情况的实时视图。

Visual GC插件最常见的用例是监视本地运行的应用程序,当应用程序开发人员或性能专家想要一种简单的方法来获得关于应用程序测试运行期间GC一般行为的可视化信息时。

JVisualVM

在图表的左侧,你可以看到不同内存池当前使用情况的实时视图:metspace或Permanent Generation、Old Generation、Eden Generation和两个Survivor space。

在右侧,前两个图表与GC无关,公开了JIT编译时间和类装入时间。下面的六个图表显示了内存池使用的历史记录、每个池的GC收集次数和该池的累计GC时间。此外,每个池的当前大小、峰值使用量和最大大小也会显示出来。

下面是当前驻留在Young代中的对象年龄的分布。

与纯JMX工具相比,JVisualVM的VisualGC附加组件确实提供了对JVM更好的了解,因此,如果你的工具包中只有这两个工具,请选择VisualGC插件。

如果你可以使用本章中提到的任何其他解决方案,请继续阅读。其他选项可以给你更多的信息和更好的见解。然而,在“profiler”一节中讨论了一个特定的用例,JVisualVM适合该用例—即分配分析,因此我们绝不是在一般情况下降级该工具,只是针对特定的用例。

jstat

下一个要研究的工具也是标准JDK发行版的一部分。该工具称为“jstat”——Java虚拟机统计信息监控工具。

这是一个命令行工具,可用于从正在运行的JVM获取指标。连接的JVM可以是本地的,也可以是远程的。

通过从命令行运行”jstat -option”,可以获得jstat能够公开的指标的完整列表。最常用的选项有:

+-----------------+---------------------------------------------------------------+
|     Option      |                          Displays...                          |
|-----------------|---------------------------------------------------------------|
|class            | Statistics on the behavior of the class loader                |
|compiler         | Statistics  on  the behavior of the HotSpot Just-In-Time com- |
|                 | piler                                                         |
|gc               | Statistics on the behavior of the garbage collected heap      |
|gccapacity       | Statistics of the capacities of  the  generations  and  their |
|                 | corresponding spaces.                                         |
|gccause          | Summary  of  garbage collection statistics (same as -gcutil), |
|                 | with the cause  of  the  last  and  current  (if  applicable) |
|                 | garbage collection events.                                    |
|gcnew            | Statistics of the behavior of the new generation.             |
|gcnewcapacity    | Statistics of the sizes of the new generations and its corre- |
|                 | sponding spaces.                                              |
|gcold            | Statistics of the behavior of the old and  permanent  genera- |
|                 | tions.                                                        |
|gcoldcapacity    | Statistics of the sizes of the old generation.                |
|gcpermcapacity   | Statistics of the sizes of the permanent generation.          |
|gcutil           | Summary of garbage collection statistics.                     |
|printcompilation | Summary of garbage collection statistics.                     |
+-----------------+---------------------------------------------------------------+

此工具对于快速了解JVM运行状况以了解垃圾收集器是否按照预期行为非常有用。例如,你可以通过jstat -gc -t PID 1运行它,其中PID是你想要监视的JVM的进程ID。

你可以通过运行jps来获取PID,以获得正在运行的Java进程列表。因此,jstat每隔一秒就会向标准输出输出一行,类似于下面的示例:

Timestamp  S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
200.0  	 8448.0 8448.0 8448.0  0.0   67712.0  67712.0   169344.0   169344.0  21248.0 20534.3 3072.0 2807.7     34    0.720  658   133.684  134.404
201.0 	 8448.0 8448.0 8448.0  0.0   67712.0  67712.0   169344.0   169343.2  21248.0 20534.3 3072.0 2807.7     34    0.720  662   134.612  135.332
202.0 	 8448.0 8448.0 8102.5  0.0   67712.0  67598.5   169344.0   169343.6  21248.0 20534.3 3072.0 2807.7     34    0.720  667   135.340  136.060
203.0 	 8448.0 8448.0 8126.3  0.0   67712.0  67702.2   169344.0   169343.6  21248.0 20547.2 3072.0 2807.7     34    0.720  669   136.178  136.898
204.0 	 8448.0 8448.0 8126.3  0.0   67712.0  67702.2   169344.0   169343.6  21248.0 20547.2 3072.0 2807.7     34    0.720  669   136.178  136.898
205.0 	 8448.0 8448.0 8134.6  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  671   136.234  136.954
206.0 	 8448.0 8448.0 8134.6  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  671   136.234  136.954
207.0 	 8448.0 8448.0 8154.8  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  673   136.289  137.009
208.0 	 8448.0 8448.0 8154.8  0.0   67712.0  67712.0   169344.0   169343.5  21248.0 20547.2 3072.0 2807.7     34    0.720  673   136.289  137.009

让我们使用jstat手册中对输出属性的解释来解释上面的输出。运用所学知识,我们可以看到:

  • jstat在JVM启动后200秒连接到JVM。该信息显示在第一列”Timestamp”中。正如在同一列中看到的,jstat每秒钟从JVM获取一次信息,命令中给出的“1s”参数中指定了这一点。
  • 从第一行我们可以看到,到目前为止,年轻代已经被清理了34次,整个堆已经被清理了658次,分别由”YGC”和”FGC”列表示。
  • 如”YGCT”列所示,年轻代垃圾收集器总共运行了0.720秒。
  • 如”FGCT”列所示,整个GC的总持续时间为133.684秒。这应该会立即引起我们的注意——我们可以看到,在JVM运行的总200秒中,66%的时间花在了Full GC周期中。

当我们看下一行(稍后获取信息)时,问题变得更加清晰:

  • 现在我们可以看到,在上次jstat打印“FGC”列中显示的数据之间的一秒钟内,又运行了4个Full gc。
  • 这四个GC暂停几乎用了整整一秒——从“FGCT”列的差异可以看出。与第一行相比,Full GC运行了928毫秒,即总时间的92.8%。
  • 同时,从“OC”和“OU”列中可以看出,从几乎所有旧代容量169,344.0 KB(“OC”)中可以看出,在四个收集周期尝试完成所有清理工作之后,169,344.2 KB(“OU”)仍然在使用中。在928毫秒内清除800字节不应该被视为正常行为。

只有jstat输出中的这两行让我们了解到应用程序中存在严重错误。对下一行应用相同的分析,我们可以确认问题仍然存在,而且变得更糟。

JVM几乎停止了运行,GC消耗了90%以上的可用计算能力。由于所有这些清理,几乎所有的老年代仍然在使用,进一步证实了我们的怀疑。

事实上,这个示例在java.lang.OutOfMemoryError: GC overhead limit exceede错误之后不到一分钟就消失了,消除了对事情是否真的糟糕的最后剩余的怀疑。

从示例中可以看出,jstat输出可以快速揭示JVM运行状况的症状,即行为不当的垃圾收集器。作为一般准则,只要查看一下jstat输出就会很快发现以下症状:

  • 最后一列“GCT”中的变化,与“Timestamp”列中的JVM总运行时相比,给出了关于垃圾收集开销的信息。如果你看到,与总运行时相比,该列中的值每秒钟都在显著增加,那么就会暴露出很高的开销。有多少GC开销是可以容忍的是特定于应用程序的,应该由你手边的性能需求来决定,但作为基本原则,任何超过10%的开销都是值得怀疑的。
  • 跟踪年轻GC计数和Full GC计数的“YGC”和“FGC”列的快速变化也容易暴露问题。堆积时GC暂停太频繁,会为应用程序线程添加许多STW,从而影响吞吐量。
  • 当你看到老年代的“OU”列中使用几乎等于最大容量老年代的“OC”列,在“FGC”列计数增加后没有减少,这表明已经发生了老代收集,你暴露了GC性能不佳的另一个症状。

GC logs

gc相关信息的下一个来源可以通过垃圾收集器日志访问。由于GC日志是在JVM中构建的,所以它(可以说)为你提供了关于垃圾收集器活动的最有用和最全面的概述。

GC日志是事实上的标准,应该作为垃圾收集器评估和优化的最终真实来源来引用。

垃圾收集器日志是纯文本的,可以由JVM打印到标准输出,也可以重定向到文件。

有许多与GC日志记录相关的JVM选项。例如,你可以记录应用程序在每个GC事件之前和期间停止的总时间(-XX:+PrintGCApplicationStoppedTime),或者暴露收集的不同引用类型的信息(-XX:+PrintReferenceGC)。

每个JVM记录日志的最小值可以通过在启动脚本中指定以下参数来实现:

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:<filename>

这将指示JVM将每个GC事件打印到日志文件中,并将每个事件的时间戳添加到日志中。暴露给日志的确切信息取决于所使用的GC算法。当使用ParallelGC时,输出应该如下所示:

199.879: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1473386 secs] [Times: user=0.43 sys=0.01, real=0.15 secs]
200.027: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1567794 secs] [Times: user=0.41 sys=0.00, real=0.16 secs]
200.184: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1621946 secs] [Times: user=0.43 sys=0.00, real=0.16 secs]
200.346: [Full GC (Ergonomics) [PSYoungGen: 64000K->63998K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1547695 secs] [Times: user=0.41 sys=0.00, real=0.15 secs]
200.502: [Full GC (Ergonomics) [PSYoungGen: 64000K->63999K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1563071 secs] [Times: user=0.42 sys=0.01, real=0.16 secs]
200.659: [Full GC (Ergonomics) [PSYoungGen: 64000K->63999K(74240K)] [ParOldGen: 169318K->169318K(169472K)] 233318K->233317K(243712K), [Metaspace: 20427K->20427K(1067008K)], 0.1538778 secs] [Times: user=0.42 sys=0.00, real=0.16 secs]

从日志可以得出:

  • 在JVM启动后大约200秒提取日志。
  • 在日志中显示的780毫秒期间,JVM为GC暂停了5次(我们排除了第6次暂停,因为它开始时没有在当前的时间戳上结束)。所有这些暂停都是full GC暂停。
  • 这些暂停的总持续时间为777毫秒,占总运行时间的99.6%。
  • 同时,从老年代的容量和消耗来看,在GC反复尝试释放一些内存之后,几乎所有的老年代容量(169,472 kB)仍然被使用(169,318 K)。

从输出中,我们可以确认应用程序在GC方面的性能不佳。JVM几乎停止了运行,GC消耗了99%以上的可用计算能力。

由于所有这些清理,几乎所有的老年代仍然在使用,进一步证实了我们的怀疑。示例应用程序(与前一节jstat中使用的应用程序相同)在使用java.lang.OutOfMemoryError: GC overhead limit exceeded错误后几分钟就消失了,确认问题很严重。

从示例中可以看出,GC日志是很有价值的输入,可以从行为不当的垃圾收集器方面揭示JVM运行状况的症状。作为一般指导原则,仅通过查看GC日志就可以迅速发现以下症状:

  • GC开销太大。当GC暂停的总时间太长时,应用程序的吞吐量就会受到影响。这个限制是特定于应用程序的,但作为一般规则,任何超过10%的内容都是可疑的。
  • 一次停顿过长。每当单个暂停开始花费太长时间时,应用程序的延迟就会开始受到影响。例如,当延迟需求要求应用程序中的事务完成时间小于1,000毫秒时,你不能容忍任何GC暂停时间超过1,000毫秒。
  • 老年代的消费处于极限。即使在几个完整的GC周期之后,只要老年代仍然接近完全利用,就会出现GC成为瓶颈的情况,这要么是由于资源配置不足,要么是由于内存泄漏。这个症状也总是会触发GC开销。

正如我们所看到的,GC日志可以为我们提供关于JVM中与垃圾收集相关的操作的非常详细的信息。然而,对于除了最琐碎的应用程序之外的所有应用程序,这将导致大量的数据,这些数据往往很难被人类阅读和解释。

GCViewer

处理GC日志中的信息泛滥的一种方法是为GC日志文件编写自定义解析器来可视化信息。在大多数情况下,由于产生信息的不同GC算法的复杂性,这不是一个合理的决定。相反,一个好的方法是从一个已经存在的解决方案开始:GCViewer

GCViewer是一个用于解析和分析GC日志文件的开源工具。GitHub的网页提供了所有指标的完整描述。下面我们将回顾使用这个工具的最常见的方法。

第一步是获取有用的垃圾收集日志文件。它们应该反映出在此性能优化会话期间你感兴趣的应用程序的使用场景。

当你收到日志后,你可以将它输入GCViewer查看类似如下的结果:

GCViewer

图表区域专门用于GC事件的可视化表示。可用的信息包括所有内存池和GC事件的大小。在上面的图片中,只有两个指标是可视化的:使用的堆总数是用蓝色的线显示的,个别GC暂停持续时间下面是黑色的条。

从这张图中我们可以看到的第一件有趣的事情是内存使用量的快速增长。在大约一分钟内,总堆消耗几乎达到可用的最大堆。

这表明存在一个问题——几乎所有堆都被消耗掉了,新的分配无法继续,从而触发频繁的全GC周期。应用程序要么正在泄漏内存,要么被设置为以供应不足的堆大小运行。

图表中的下一个问题是GC暂停的频率和持续时间。我们可以看到,在最初的30秒之后,GC几乎一直在运行,最长的暂停时间超过1.4秒。

在右边有一个带有三个标签的小面板。在“Summary”选项卡下,最有趣的数字是“吞吐量”和“GC暂停数”,以及“完整GC暂停数”。吞吐量显示应用程序运行时中用于运行应用程序的部分,而不是用于垃圾收集的部分。

在我们的示例中,我们面临6.28%的吞吐量。这意味着93.72%的CPU时间花在GC上。这是应用程序遭受痛苦的一个明显症状——它不是把宝贵的CPU周期花在实际工作上,而是把大部分时间花在试图清除垃圾上。

下一个有趣的选项卡是“Pause”:

GCViewer-Pause

“Pause”选项卡公开GC暂停的总数、平均值、最小值和最大值,分别作为总暂停和次要/主要暂停。

通过优化应用程序以实现低延迟,可以初步了解你是否面临过长的暂停。同样,我们可以确认累计的634.59秒的暂停时间和3938个GC暂停的总数都太高了,考虑到总运行时仅略高于11分钟。

更多关于GC事件的详细信息可以从主区域的“Event details”选项卡中获得:

GCViewer-Event

在这里,你可以看到日志中记录的所有重要GC事件的摘要:次要和主要暂停和并发,而不是STW的GC事件。

在我们的例子中,我们可以看到一个明显的“赢家”,在这种情况下,full GC事件对吞吐量和延迟的贡献最大,再次确认3928个full GC暂停需要634秒才能完成。

从示例中可以看到,GCViewer可以快速可视化症状,这些症状告诉我们JVM是否存在行为不当的垃圾收集器。作为一般准则,可以快速显示下列症状,从而可视化GC的行为:

  • 低的吞吐量。当应用程序的吞吐量下降并降至可容忍的水平以下时,应用程序用于做有用工作的总时间就会减少。什么是“可容忍的”取决于你的应用程序及其使用场景。一条经验法则说,任何低于90%的值都应该引起你的注意,可能需要进行GC优化。
  • 单个GC暂停时间过长。每当单个暂停开始花费太长时间时,应用程序的延迟就会开始受到影响。例如,当延迟需求要求应用程序中的事务完成时间小于1,000毫秒时,你不能容忍任何GC暂停时间超过1,000毫秒。
  • 高堆消费。即使在几个full GC周期之后,只要老年代仍然接近完全利用,你就会面临应用程序处于极限的情况,这可能是由于资源配置不足或内存泄漏造成的。此症状也总是对吞吐量产生重大影响。

一般来说,可视化GC日志肯定是我们推荐的。与直接处理冗长而复杂的GC日志不同,你可以访问人类可以理解的相同信息的可视化。

Profilers

下一组要介绍的工具是profilers。与前面介绍的工具不同,gc相关的领域是profilers提供的功能的子集。在本节中,我们只关注profilers与gc相关的功能。

hprof

与JDK发行版绑定的是hprof。由于它在所有环境中都存在,所以在收集信息时要考虑的第一个分析器。

使用hprof运行应用程序时,你需要修改JVM的启动脚本,类似如下示例:

java -agentlib:hprof=heap=sites com.yourcompany.YourApplication

在应用程序退出时,它将把分配信息转储到一个java.hprof.txt文件到工作目录。用你选择的文本编辑器打开文件,搜索短语SITES BEGIN,给你类似以下信息:

SITES BEGIN (ordered by live bytes) Tue Dec  8 11:16:15 2015
          percent          live          alloc'ed  stack class
 rank   self  accum     bytes objs     bytes  objs trace name
    1  64.43% 4.43%   8370336 20121  27513408 66138 302116 int[]
    2  3.26% 88.49%    482976 20124   1587696 66154 302104 java.util.ArrayList
    3  1.76% 88.74%    241704 20121   1587312 66138 302115 eu.plumbr.demo.largeheap.ClonableClass0006
    ... cut for brevity ...
SITES END

从上面,我们可以看到按每个分配创建的对象数量排列的分配。第一行显示,64.43%的对象是在数字302116标识的站点上创建的整数数组(int[])。在文件中搜索“TRACE 302116”可以得到以下信息:

TRACE 302116:
	eu.plumbr.demo.largeheap.ClonableClass0006.<init>(GeneratorClass.java:11)
	sun.reflect.GeneratedConstructorAccessor7.newInstance(<Unknown Source>:Unknown line)
	sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
	java.lang.reflect.Constructor.newInstance(Constructor.java:422)

现在,知道了在ClonableClass0006构造函数中有64.43%的对象被分配为整数数组,在第11行中,你可以继续优化代码以减少GC的负担。

Java VisualVM

JVisualVM在本章中再次出现。在第一部分中,我们将JVisualVM从监视JVM GC行为的工具列表中排除,但在本部分中,我们将演示它在分配分析方面的优势。

将JVisualVM附加到JVM是通过GUI完成的,在GUI中你可以将分析器附加到正在运行的JVM。在附加分析器之后:

  1. 打开Profiler选项卡,并确保在“设置”复选框下,你已经启用了Record allocations stack traces
  2. 点击Memory按钮开始内存配置。
  3. 让应用程序运行一段时间,以收集足够的对象分配信息。
  4. 点击Snapshot按钮。这将为你提供所收集的分析信息的快照。

完成上述步骤后,你将获得类似以下的信息: JVisualVM

从上面,我们可以看到按每个类创建的对象数量排序的分配。在第一行中,我们可以看到绝大多数分配的对象都是int[]数组。通过右键单击该行,你可以访问这些对象被分配的所有堆栈跟踪: JVisualVM分配

与hprof相比,JVisualVM使信息更易于处理—例如,在上面的截图中,你可以看到int[]的所有分配跟踪都暴露在单个视图中,因此你可以避免匹配不同分配跟踪的潜在重复过程。

GC调优:实践

应用程序中的错误可能是由JVM性能差和其他复杂的原因造成的。

本章涵盖了垃圾收集可能遇到的几个典型性能问题。这里给出的示例是从实际应用程序中派生出来的,但是为了清晰起见进行了简化。

高分配率

分配率是在通信时使用的术语,指每个时间单元分配的内存数量。通常它以MB/sec表示,但如果你愿意,也可以使用PB/year。所以这就是所有的——没有魔法,只是你在Java代码中分配的内存数量在一段时间内的测量。

过高的分配率可能会给应用程序的性能带来问题。在JVM上运行时,垃圾收集带来的巨大开销会暴露出这个问题。

如何衡量分配率?

度量分配率的一种方法是通过为JVM指定-XX:+PrintGCDetails -XX:+PrintGCTimeStamps标志来打开GC日志记录。JVM现在开始记录GC暂停,类似如下:

0.291: [GC (Allocation Failure) [PSYoungGen: 33280K->5088K(38400K)] 33280K->24360K(125952K), 0.0365286 secs] [Times: user=0.11 sys=0.02, real=0.04 secs] 
0.446: [GC (Allocation Failure) [PSYoungGen: 38368K->5120K(71680K)] 57640K->46240K(159232K), 0.0456796 secs] [Times: user=0.15 sys=0.02, real=0.04 secs] 
0.829: [GC (Allocation Failure) [PSYoungGen: 71680K->5120K(71680K)] 112800K->81912K(159232K), 0.0861795 secs] [Times: user=0.23 sys=0.03, real=0.09 secs]

从上面的GC日志中,我们可以计算分配率,将其作为上次收集完成后和下一次收集开始之前年轻代的大小之间的差值。使用上面的例子,我们可以提取以下信息:

  • 在启动JVM后的291毫秒内,创建了33280 K的对象。第一个小GC事件清除了年轻代,之后年轻代中还剩下5,088 K的对象。
  • 在启动后的446毫秒,年轻代的占有率增长到38368 K,触发了下一个GC,成功地将年轻代的占有率减少到5120 K。
  • 在启动后的829毫秒,年轻代的大小为71680 K,而GC再次将其缩小到5120 K。

这个数据可以用下表来表示,并将分配率计算为年轻入住率的delta:

Event Time Young before Young after Allocated during Allocation rate
1st GC 291ms 33,280KB 5,088KB 33,280KB 114MB/sec
2nd GC 446ms 38,368KB 5,120KB 33,280KB 215MB/sec
3rd GC 829ms 71,680KB 5,120KB 66,560KB 174MB/sec
Total 829ms N/A N/A 133,120KB 161MB/sec

有了这些信息,我们就可以说这个特定的软件在测量期间的分配率是161 MB/秒

我为什么要在乎?

在测量分配率之后,我们可以了解分配率的变化如何通过增加或减少GC暂停的频率影响应用程序吞吐量。

首先,你应该注意到只有清除年轻代时的少量GC暂停会受到影响。GC暂停清理老年代的频率和持续时间都不会直接受到分配率的影响,而是受到提升率的影响,我们将在下一节中单独讨论这个术语。

既然我们可以只关注Minor GC暂停,那么接下来应该研究年轻代中的不同内存池。

当分配在Eden中进行时,我们可以立即了解Eden的大小如何影响分配率。因此,我们可以假设增加Eden的大小将减少小GC暂停的频率,从而允许应用程序维持更快的分配速率。

事实上,当使用-XX:NewSize -XX:MaxNewSize-XX:SurvivorRatio参数以不同的Eden大小运行相同的应用程序时,我们可以看到分配率的两倍差异。

  • 使用100 M的Eden重新运行将分配率降低到100 MB/秒以下。
  • 将Eden的大小增加到1 GB将分配速率增加到略低于200 MB/秒。

如果你仍然想知道这是如何实现的—如果不那么频繁地停止应用程序的GC线程,你可以做更多有用的工作。更有用的工作还包括创建更多对象,从而支持增加的分配率。

示例

public class BoxingFailure {
  private static volatile Double sensorValue;

  private static void readSensor() {
    while(true) sensorValue = Math.random();
  }

  private static void processSensorValue(Double value) {
    if(value != null) {
      //...
    }
  }
}

正如这个类的名字所暗示的那样,这里的问题是装箱。可能是为了适应空检查,作者使sensorValue字段为大写d Double。

这个例子是一个非常常见的模式,它基于最近的值来处理计算,当获得这个值是一个昂贵的操作时。在现实世界中,它通常比获取一个随机值要昂贵得多。因此,一个线程连续地生成新值,计算线程使用它们,避免了昂贵的检索。

演示应用程序受到GC跟不上分配率的影响。验证和解决问题的方法将在下一节中给出。

我的jvm会受到影响吗?

首先,只有当应用程序的吞吐量开始下降时,你才应该担心。由于应用程序创建了太多几乎立即被丢弃的对象,小GC暂停的频率激增。在足够的负载下,这可能会导致GC对吞吐量产生重大影响。

当你遇到这样的情况时,你将会遇到一个类似于以下简短片段的日志文件,该片段是从上一节介绍的演示应用程序的GC日志中提取的。

应用程序以-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xmx32m命令行参数的方式启动:

2.808: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003076 secs]
2.819: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003079 secs]
2.830: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0002968 secs]
2.842: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003374 secs]
2.853: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0004672 secs]
2.864: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003371 secs]
2.875: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003214 secs]
2.886: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003374 secs]
2.896: [GC (Allocation Failure) [PSYoungGen: 9760K->32K(10240K)], 0.0003588 secs]

应该立即引起你注意的是Minor GC事件的频率。这表明有很多很多的对象正在被分配。此外,年轻代的gc后占用率仍然很低,并且没有进行完整的收集。这些症状表明GC对手边应用程序的吞吐量有重大影响。

解决方案是什么?

在某些情况下,降低高分配率的影响就像增加年轻一代的规模一样容易。

这样做本身不会降低分配率,但会导致较少的收集频率。当每次只有少数幸存者时,这种方法的好处就显现出来了。由于小GC暂停的持续时间会受到幸存对象数量的影响,因此不会显著增加。

通过使用-Xmx64m参数,当我们运行相同的演示应用程序时,结果是可见的,只是增加了堆大小和年轻代大小:

2.808: [GC (Allocation Failure) [PSYoungGen: 20512K->32K(20992K)], 0.0003748 secs]
2.831: [GC (Allocation Failure) [PSYoungGen: 20512K->32K(20992K)], 0.0004538 secs]
2.855: [GC (Allocation Failure) [PSYoungGen: 20512K->32K(20992K)], 0.0003355 secs]
2.879: [GC (Allocation Failure) [PSYoungGen: 20512K->32K(20992K)], 0.0005592 secs]

然而,仅仅增加内存并不总是一个可行的解决方案。有了上一章中关于分配分析器的知识,我们可以找出大部分垃圾是在哪里产生的。

具体来说,在本例中,99%是使用readSensor方法创建的double。作为一个简单的优化,对象可以用一个基本的double替换,null可以用Double.NaN替换。

由于原始值实际上不是对象,因此不会产生垃圾,也就没有什么要收集的东西。不是在堆上分配一个新对象,而是直接覆盖现有对象中的字段。

过早提升

在解释过早提升的概念之前,我们应该先熟悉它所建立的概念—提升率。提升率是以每一时间单位从年轻代传播到年老代的数据量来衡量的。它通常以MB/s为度量单位,类似于分配率。

将长寿对象从年轻代提升到年老代是JVM的工作方式。回顾生成假设,我们现在可以构建这样一种情况,即不仅长寿命的对象最终在老的代中结束。这种预期寿命较短的对象没有在年轻代中收集,并被提升到年老代的情况称为过早提升。

清理这些短命的对象现在成为Major GC的工作,Major GC不是为频繁运行而设计的,因此会导致更长的GC暂停时间。这极大地影响了应用程序的吞吐量。

如何衡量提升率

度量提升率的一种方法是通过为JVM指定-XX:+PrintGCDetails -XX:+PrintGCTimeStamps标志来打开GC日志记录。JVM现在开始记录GC暂停,如下面的代码片段所示:

0.291: [GC (Allocation Failure) [PSYoungGen: 33280K->5088K(38400K)] 33280K->24360K(125952K), 0.0365286 secs] [Times: user=0.11 sys=0.02, real=0.04 secs] 
0.446: [GC (Allocation Failure) [PSYoungGen: 38368K->5120K(71680K)] 57640K->46240K(159232K), 0.0456796 secs] [Times: user=0.15 sys=0.02, real=0.04 secs] 
0.829: [GC (Allocation Failure) [PSYoungGen: 71680K->5120K(71680K)] 112800K->81912K(159232K), 0.0861795 secs] [Times: user=0.23 sys=0.03, real=0.09 secs]

从上面我们可以提取年轻代的大小和在收集事件之前和之后的总堆。知道年轻代的消费和总堆,很容易计算老代的消费仅仅是两者之间的增量。将GC日志中的信息表示为:

Event Time Young decreased Total decreased Promoted Promotion rate
1st GC 291ms 28,192K 8,920K 19,272K 66.2 MB/sec
2nd GC 446ms 33,248K 11,400K 21,848K 140.95 MB/sec
3rd GC 829ms 66,560K 30,888K 35,672K 93.14 MB/sec
Total 829ms     76,792K 92.63 MB/sec

将允许我们提取测量期间的晋升率。我们可以看到,平均提升率是92 MB/秒,在一段时间内最高达到140.95 MB/秒。

注意,你只能从少量GC暂停中提取此信息。完全GC暂停不会暴露提升率,因为GC日志中老年代使用情况的变化还包括主GC清理的对象。

我为什么要在乎?

与分配率类似,提升率的主要影响是GC暂停频率的变化。但是与影响次要GC事件频率的分配率不同,提升率影响主要GC事件的频率。

让我来解释一下——你向老年代推广的东西越多,你就会越快地把它填满。更快地填充老代意味着清除老代的GC事件频率将增加。 GC

正如我们在前面的章节中所展示的,完整的垃圾收集通常需要更多的时间,因为它们必须与更多的对象交互,并执行额外的复杂活动,如碎片整理。

示例

public class PrematurePromotion {

   private static final Collection<byte[]> accumulatedChunks = new ArrayList<>();

   private static void onNewChunk(byte[] bytes) {
       accumulatedChunks.add(bytes);

       if(accumulatedChunks.size() > MAX_CHUNKS) {
           processBatch(accumulatedChunks);
           accumulatedChunks.clear();
       }
   }
}

演示应用程序受到GC的过早提升的影响。验证和解决问题的方法将在下一节中给出。

我的jvm会受到影响吗?

一般来说,过早晋升的症状有以下几种:

  • 应用程序在短时间内频繁地运行Full GC
  • 每次full GC之后,老年代的消耗很低,通常小于老年代总大小的10-20%。
  • 面对晋升率接近分配率。

在一个简短且易于理解的演示应用程序中展示这一点有点棘手,所以我们将稍微欺骗一下,将对象的保留期设置为比默认情况下更早一点。

如果我们使用一组特定的GC参数运行演示(-Xmx24m -XX:NewSize=16m -XX:MaxTenuringThreshold=1),我们将在垃圾收集日志中看到:

2.176: [Full GC (Ergonomics) [PSYoungGen: 9216K->0K(10752K)] [ParOldGen: 10020K->9042K(12288K)] 19236K->9042K(23040K), 0.0036840 secs]
2.394: [Full GC (Ergonomics) [PSYoungGen: 9216K->0K(10752K)] [ParOldGen: 9042K->8064K(12288K)] 18258K->8064K(23040K), 0.0032855 secs]
2.611: [Full GC (Ergonomics) [PSYoungGen: 9216K->0K(10752K)] [ParOldGen: 8064K->7085K(12288K)] 17280K->7085K(23040K), 0.0031675 secs]
2.817: [Full GC (Ergonomics) [PSYoungGen: 9216K->0K(10752K)] [ParOldGen: 7085K->6107K(12288K)] 16301K->6107K(23040K), 0.0030652 secs]

乍一看,过早的晋升似乎不是问题所在。事实上,每一个周期,老年代的占有率似乎都在下降。然而,如果很少或没有对象被提升,我们就不会看到很多full gc。

对于这种GC行为有一个简单的解释:当许多对象被提升到老年代时,一些现有的对象被收集。这给人的印象是老年代的使用正在减少,而实际上,有一些对象正在不断提升,触发了full GC。

解决方案是什么?

简而言之,要解决这个问题,我们需要让缓冲数据适合年轻一代。有两种简单的方法可以做到这一点。

第一种方法是在JVM启动时使用-Xmx64m -XX:NewSize=32m参数来增加年轻代的大小。在配置中使用这个更改运行应用程序将使Full GC事件更少发生,而几乎不会影响次要收集的持续时间:

2.251: [GC (Allocation Failure) [PSYoungGen: 28672K->3872K(28672K)] 37126K->12358K(61440K), 0.0008543 secs]
2.776: [GC (Allocation Failure) [PSYoungGen: 28448K->4096K(28672K)] 36934K->16974K(61440K), 0.0033022 secs]

在这种情况下,另一种方法是简单地减少批大小,这也会得到类似的结果。选择正确的解决方案很大程度上取决于应用程序中实际发生的情况。

在某些情况下,业务逻辑不允许减少批处理大小。在这种情况下,增加可用内存或重新分配有利于年轻代是可能的。

如果两者都不是可行的选择,那么也许可以优化数据结构以减少内存消耗。但在这种情况下,总体目标仍然是一样的:让瞬态数据适合年轻代。

弱引用、软引用和虚引用

另一类影响GC的问题与应用程序中使用非强引用有关。虽然在很多情况下这可能有助于避免不必要的OutOfMemoryError,但大量使用此类引用可能会严重影响垃圾收集影响应用程序性能的方式。

我为什么要在乎?

在使用弱引用时,你应该注意弱引用的垃圾收集方式。每当GC发现一个对象是弱可达的(即,对该对象的最后一个剩余引用是弱引用),它就被放到相应的ReferenceQueue上,并有资格进行终结。

然后可以轮询这个引用队列并执行相关的清除活动。这种清理的典型示例是从缓存中删除现在丢失的键。

这里的技巧是,此时你仍然可以创建对对象的新的强引用,因此在最终完成并回收它之前,GC必须再次检查是否可以这样做。因此,弱引用的对象不会被回收以进行额外的GC周期。

弱引用实际上比你想象的要常见得多。许多缓存解决方案使用弱引用构建实现,因此,即使你没有直接在代码中创建任何弱引用,你的应用程序仍然很有可能大量使用弱引用对象。

在使用软引用时,你应该记住软引用的收集程度远低于弱引用。具体发生的时间点没有指定,取决于JVM的实现。

通常,软引用的集合只是在内存耗尽之前的最后一招。这意味着你可能会发现自己面临比预期更频繁或更长的完整GC暂停的情况,因为在老年代中有更多的对象处于静止状态。

当使用虚引用时,你必须手动进行内存管理,以便将此类引用标记为符合垃圾收集的条件。这是危险的,因为对javadoc的表面一瞥可能会让人相信它们是完全安全的:

为了确保可回收对象保持原样,幻像引用的引用可能不会被检索:幻像引用的get方法总是返回null。

与软引用和弱引用不同,虚引用在进入队列时不会被垃圾回收器自动清除。通过虚引用可访问的对象将保持此状态,直到所有此类引用被清除或其本身不可访问为止。

这是对的,我们必须手动清除虚引用,否则将面临JVM开始死于OutOfMemoryError的风险。之所以首先存在幻影引用,是因为这是唯一的方法,可以通过通常的方法确定对象何时变得不可访问。

与软引用或弱引用不同,你不能复活虚拟可及对象。

示例

让我们看一下另一个演示应用程序,它分配了许多对象,这些对象在小型垃圾收集期间被成功回收。

记住修改前一节关于提升率的保留期阈值的技巧,我们可以使用-Xmx24m -XX:NewSize=16m -XX:MaxTenuringThreshold=1运行这个应用程序,并在GC日志中查看:

2.330: [GC (Allocation Failure)  20933K->8229K(22528K), 0.0033848 secs]
2.335: [GC (Allocation Failure)  20517K->7813K(22528K), 0.0022426 secs]
2.339: [GC (Allocation Failure)  20101K->7429K(22528K), 0.0010920 secs]
2.341: [GC (Allocation Failure)  19717K->9157K(22528K), 0.0056285 secs]
2.348: [GC (Allocation Failure)  21445K->8997K(22528K), 0.0041313 secs]
2.354: [GC (Allocation Failure)  21285K->8581K(22528K), 0.0033737 secs]
2.359: [GC (Allocation Failure)  20869K->8197K(22528K), 0.0023407 secs]
2.362: [GC (Allocation Failure)  20485K->7845K(22528K), 0.0011553 secs]
2.365: [GC (Allocation Failure)  20133K->9501K(22528K), 0.0060705 secs]
2.371: [Full GC (Ergonomics)  9501K->2987K(22528K), 0.0171452 secs]

在这种情况下,full GC是相当罕见的。然而,如果应用程序也开始对这些创建的对象创建弱引用(-Dweak.refs=true),情况可能会发生巨大的变化。

这样做可能有很多原因,从在弱散列映射中使用对象作为键开始,到分配配置结束。在任何情况下,在这里使用弱引用可能会导致以下结果:

2.059: [Full GC (Ergonomics)  20365K->19611K(22528K), 0.0654090 secs]
2.125: [Full GC (Ergonomics)  20365K->19711K(22528K), 0.0707499 secs]
2.196: [Full GC (Ergonomics)  20365K->19798K(22528K), 0.0717052 secs]
2.268: [Full GC (Ergonomics)  20365K->19873K(22528K), 0.0686290 secs]
2.337: [Full GC (Ergonomics)  20365K->19939K(22528K), 0.0702009 secs]
2.407: [Full GC (Ergonomics)  20365K->19995K(22528K), 0.0694095 secs]

正如我们所看到的,现在有许多full GC,而且GC的持续时间是一个数量级的长!这是另一个过早提升的例子,但这一次有点棘手。

当然,根本原因在于弱引用。在我们添加它们之前,应用程序创建的对象在被提升到老年代之前就已经死亡了。

但是添加了这个功能后,它们现在需要等待一个额外的GC回合,以便对它们进行适当的清理。和之前一样,一个简单的解决方案是通过指定-Xmx64m -XX:NewSize=32m来增加年轻代的大小:

2.328: [GC (Allocation Failure)  38940K->13596K(61440K), 0.0012818 secs]
2.332: [GC (Allocation Failure)  38172K->14812K(61440K), 0.0060333 secs]
2.341: [GC (Allocation Failure)  39388K->13948K(61440K), 0.0029427 secs]
2.347: [GC (Allocation Failure)  38524K->15228K(61440K), 0.0101199 secs]
2.361: [GC (Allocation Failure)  39804K->14428K(61440K), 0.0040940 secs]
2.368: [GC (Allocation Failure)  39004K->13532K(61440K), 0.0012451 secs]

这些对象现在在Minor GC期间再次被回收。

当在下一个演示应用程序中使用软引用时,情况会更糟。软可达对象不会被回收,直到应用程序面临获得OutOfMemoryError的风险。在演示应用程序中用软引用替换弱引用会立即出现更多Full GC事件:

2.162: [Full GC (Ergonomics)  31561K->12865K(61440K), 0.0181392 secs]
2.184: [GC (Allocation Failure)  37441K->17585K(61440K), 0.0024479 secs]
2.189: [GC (Allocation Failure)  42161K->27033K(61440K), 0.0061485 secs]
2.195: [Full GC (Ergonomics)  27033K->14385K(61440K), 0.0228773 secs]
2.221: [GC (Allocation Failure)  38961K->20633K(61440K), 0.0030729 secs]
2.227: [GC (Allocation Failure)  45209K->31609K(61440K), 0.0069772 secs]
2.234: [Full GC (Ergonomics)  31609K->15905K(61440K), 0.0257689 secs]

这里的国王是在第三个演示应用中看到的虚引用。使用与前面相同的参数集运行演示程序,得到的结果与使用弱引用时的结果非常相似。实际上,由于本节开始时描述的终结的不同,full GC暂停的数量要小得多。

然而,添加一个禁用幻像引用清除的标志(-Dno.ref.clearing=true)会很快得到如下结果:

4.180: [Full GC (Ergonomics)  57343K->57087K(61440K), 0.0879851 secs]
4.269: [Full GC (Ergonomics)  57089K->57088K(61440K), 0.0973912 secs]
4.366: [Full GC (Ergonomics)  57091K->57089K(61440K), 0.0948099 secs]
Exception in thread "main" java.lang.OutOfMemoryError: Java heap space

在使用虚引用时必须格外小心,并始终及时清除虚引用可达对象。如果不这样做,可能会以OutOfMemoryError结束。=

我的jvm会受到影响吗?

作为一般建议,考虑启用-XX:+PrintReferenceGC JVM选项,以查看不同引用对垃圾收集的影响。如果我们从WeakReference的例子中把它添加到应用程序中,我们会看到:

2.173: [Full GC (Ergonomics) 2.234: [SoftReference, 0 refs, 0.0000151 secs]2.234: [WeakReference, 2648 refs, 0.0001714 secs]2.234: [FinalReference, 1 refs, 0.0000037 secs]2.234: [PhantomReference, 0 refs, 0 refs, 0.0000039 secs]2.234: [JNI Weak Reference, 0.0000027 secs][PSYoungGen: 9216K->8676K(10752K)] [ParOldGen: 12115K->12115K(12288K)] 21331K->20792K(23040K), [Metaspace: 3725K->3725K(1056768K)], 0.0766685 secs] [Times: user=0.49 sys=0.01, real=0.08 secs] 
2.250: [Full GC (Ergonomics) 2.307: [SoftReference, 0 refs, 0.0000173 secs]2.307: [WeakReference, 2298 refs, 0.0001535 secs]2.307: [FinalReference, 3 refs, 0.0000043 secs]2.307: [PhantomReference, 0 refs, 0 refs, 0.0000042 secs]2.307: [JNI Weak Reference, 0.0000029 secs][PSYoungGen: 9215K->8747K(10752K)] [ParOldGen: 12115K->12115K(12288K)] 21331K->20863K(23040K), [Metaspace: 3725K->3725K(1056768K)], 0.0734832 secs] [Times: user=0.52 sys=0.01, real=0.07 secs] 
2.323: [Full GC (Ergonomics) 2.383: [SoftReference, 0 refs, 0.0000161 secs]2.383: [WeakReference, 1981 refs, 0.0001292 secs]2.383: [FinalReference, 16 refs, 0.0000049 secs]2.383: [PhantomReference, 0 refs, 0 refs, 0.0000040 secs]2.383: [JNI Weak Reference, 0.0000027 secs][PSYoungGen: 9216K->8809K(10752K)] [ParOldGen: 12115K->12115K(12288K)] 21331K->20925K(23040K), [Metaspace: 3725K->3725K(1056768K)], 0.0738414 secs] [Times: user=0.52 sys=0.01, real=0.08 secs]

与往常一样,只有当你确定GC对应用程序的吞吐量或延迟有影响时,才应该分析此信息。在这种情况下,你可能需要检查日志的这些部分。

通常,在每个GC周期中清除的引用数量非常少,在许多情况下正好为零。但是,如果情况并非如此,并且应用程序花费了大量的时间来清除引用,或者只是清除了很多引用,那么就需要进行进一步的调查。

解决方案是什么?

当你已经验证了应用程序实际上正在遭受弱引用、软引用或虚引用的错误、滥用或过度使用时,解决方案通常涉及更改应用程序的内在逻辑。这是非常具体的应用程序和通用的指导方针,因此很难提供。然而,需要记住的一些通用解决方案是:

  • 弱引用—-如果问题是由特定内存池的消耗增加引发的,那么增加相应池(可能还包括总堆)可以帮助你解决问题。正如在示例部分中所看到的,增加总堆和年轻代的大小可以减轻这种痛苦。
  • 虚引用—-确保你确实清除了引用。很容易忽略某些角落病例和清理线程无法跟上步伐的队列或完全停止清除队列,施加很多压力GC和创建一个可能到最后只能依靠一个OutOfMemoryError。
  • 软引用—-当软引用被确定为问题的根源时,缓解压力的唯一真正方法是改变应用程序的内在逻辑。

其他示例

前几章讨论了与行为不良的GC相关的最常见问题。不幸的是,有一长串更具体的情况,你不能应用前几章的知识。本节描述你可能会遇到的一些不寻常的问题。

RMI & GC

当你的应用程序通过RMI发布或消费服务时,JVM会定期启动完整的GC,以确保本地未使用的对象也不会占用另一端的空间。

请记住,即使你没有明确地在代码中通过RMI发布任何内容,第三方库或实用程序仍然可以打开RMI端点。例如,一个常见的罪魁祸首是JMX,如果远程连接到它,它将使用RMI底层发布数据。

这个问题暴露于看似不必要的周期性full GC暂停。当你检查老代的消耗时,通常不会对内存造成压力,因为老代中有大量的空闲空间,但是会触发full GC,从而停止应用程序线程。

这种通过System.gc()删除远程引用的行为是由sun.rmi.transport.ObjectTable类触发的,该类请求定期运行sun.misc.GC.requestLatency()方法中指定的垃圾收集。

对于许多应用程序来说,这是不必要的或完全有害的。要禁用这种定期GC运行,你可以为你的JVM启动脚本设置以下内容:

java -Dsun.rmi.dgc.server.gcInterval=9223372036854775807L -Dsun.rmi.dgc.client.gcInterval=9223372036854775807L com.yourcompany.YourApplication

这设置了System.gc()运行的周期为Long.MAX_VALUE;对于所有实际问题来说,这就等于永恒。

该问题的另一种解决方案是通过在JVM启动参数中指定-XX:+DisableExplicitGC来禁用对System.gc()的显式调用。然而,我们不推荐这种解决方案,因为它可能有其他副作用。

Humongous Allocations

每当你的应用程序使用G1垃圾收集算法时,就GC而言,一个称为巨大分配的现象会影响你的应用程序性能。概括一下,巨大的分配是指在G1中大于区域大小50%的分配。

频繁的大量分配可能会触发GC性能问题,考虑G1处理这种分配的方式:

  • 如果区域中包含巨大的对象,则区域中最后一个巨大的对象与区域的末端之间的空间将被使用。如果所有庞大的对象只比区域大小的一个因数大一点,那么这些未使用的空间可能会导致堆变成碎片。
  • 对于庞大对象的收集,G1并不像对于常规对象那样进行优化。这在早期的Java 8版本中尤其麻烦——直到Java 1.8u40之前,巨大区域的回收只在full GC事件期间完成。Hotspot JVM的最新版本在清理阶段的标记周期结束时释放了巨大的区域,因此这个问题对新JVM的影响已经显著降低。

要检查应用程序是否在巨大的区域中分配对象,第一步是打开类似于以下内容的GC日志:

java -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:+UseG1GC -XX:+PrintAdaptiveSizePolicy -Xmx128m MyClass

现在,当你检查日志并发现像这样的部分:

 0.106: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 60817408 bytes, allocation request: 1048592 bytes, threshold: 60397965 bytes (45.00 %), source: concurrent humongous allocation]
 0.106: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: requested by GC cause, GC cause: G1 Humongous Allocation]
 0.106: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
 0.106: [GC pause (G1 Humongous Allocation) (young) (initial-mark) 0.106: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 10.00 ms, remaining time: 190.00 ms, target pause time: 200.00 ms]

你有证据表明应用程序确实在分配巨大的对象。证据是显而易见的,GC暂停的原因被识别为G1 Humongous Allocation和“分配请求:在这里,我们可以看到应用程序试图分配一个大小为1,048,592字节的对象,这比为JVM指定的巨大区域(2mb)的50%大了16个字节。

对于humongous分配的第一个解决方案是更改区域大小,以便(大多数)分配不会超过触发humongous区域分配的50%限制。

区域大小是由JVM在启动期间根据堆的大小计算的。你可以通过在启动脚本中指定-XX:G1HeapRegionSize=XX来覆盖大小。指定的区域大小必须在1到32 mb之间,并且必须是2的幂。

此解决方案可能有副作用—增加区域大小会减少可用区域的数量,因此你需要小心并运行额外的测试集,以查看是否真的提高了应用程序的吞吐量或延迟。

一个更耗时但可能更好的解决方案是了解应用程序是否可以限制分配的大小。在这种情况下,最好的工具是分析器。通过显示带有堆栈跟踪的分配源,它们可以为你提供关于大型对象的信息。

小结

由于可能在JVM上运行的应用程序数量巨大,再加上可能为GC调整的数百个JVM配置参数,因此GC可能以许多令人震惊的方式影响应用程序的性能。

因此,没有真正的银弹方法来调优JVM以匹配你必须实现的性能目标。我们在这里试图做的是通过一些常见(和不太常见)的例子,让你大致了解如何解决这类问题。再加上工具概述和对GC工作方式的深入了解,你就有机会成功地调优垃圾收集,以提高应用程序的性能。

参考

  1. What Is Garbage Collection?