分析 Quarkus Native 启动 RSS 消耗

在 Quarkus 2.13 的开发过程中,我们发现原生模式下的启动性能有所下降。这种下降的一个关键方面是,与 Quarkus 2.7 相比,启动时的 RSS 消耗增加了约 10-15%。在这篇博文中,您将了解 Quarkus 原生 RSS 消耗调试技术,这些技术在 Quarkus 原生参考指南 中进行了描述,并用于诊断此问题。您还将了解 GraalVM 的最新更新,这些更新使得进行此类分析更加便捷。

我们的分析显示,Quarkus 2.7 的 RSS 消耗约为 ~33MB,而 Quarkus 2.13 约为 ~36MB,增加了约 10%。下面我们来看看 Quarkus 2.7.6.Final 的 RSS 消耗测量情况。

$ getting-started/target/getting-started-1.0.0-SNAPSHOT-runner -Xmx64m
...
2023-07-21 10:13:11,304 INFO  [io.quarkus] (main) getting-started 1.0.0-SNAPSHOT native (powered by Quarkus 2.7.6.Final) started in 0.023s. Listening on: http://0.0.0.0:8080

$ ps -p $(pidof getting-started-1.0.0-SNAPSHOT-runner) -o rss=
33024

同样,下面我们来看看 Quarkus 2.13.4.Final 的 RSS 消耗测量情况:在我们的环境中,RSS 消耗已增至约 ~36MB,增加了约 10%。

$ getting-started/target/getting-started-1.0.0-SNAPSHOT-runner -Xmx64m
...
2023-07-21 10:24:38,529 INFO  [io.quarkus] (main) getting-started 1.0.0-SNAPSHOT native (powered by Quarkus 2.13.4.Final) started in 0.027s. Listening on: http://0.0.0.0:8080

$ ps -p $(pidof getting-started-1.0.0-SNAPSHOT-runner) -o rss=
36608

由于 Quarkus 2.7 和 2.13 使用不同的 GraalVM 版本(21.3 vs 22.3),我们首先调查了启动时间和 RSS 消耗的增加是否是由于 GraalVM 的更改。事实证明并非如此,因为在两个 Quarkus 版本上使用相同的 GraalVM 版本仍然会导致类似的差异。

我们还分析了 JVM 模式下的启动时间,尽管我们观察到堆使用量有所增加,但在运行时 RSS 增加并不明显。因此,挑战在于理解是什么导致了 RSS 增加,这种增加似乎只影响原生模式且是 Quarkus 特有的。

在原生模式下,我们需要查找增加 RSS 的系统调用,并调查其原因。有几种系统调用可用于分配内存,例如 mallocmmap 等。但当我们分析启动时发出的系统调用时,我们发现 mmap 调用是最主要的。遵循 Brendan Gregg 的内存泄漏(和增长)火焰图指南 在 Linux 环境中,我们能够为 mmap 系统调用生成火焰图。要获得这些火焰图,我们使用 perf record 捕获 sys_enter_mmap 系统调用事件,然后使用记录的数据生成火焰图。

$ sudo perf record -e syscalls:sys_enter_mmap --call-graph dwarf \
  -- getting-started/target/getting-started-1.0.0-SNAPSHOT-runner -Xmx64m
...
2023-07-21 10:13:11,304 INFO  [io.quarkus] (main) getting-started 1.0.0-SNAPSHOT native (powered by Quarkus 2.7.6.Final) started in 0.023s. Listening on: http://0.0.0.0:8080

$ perf script -i perf.data > out.stacks

$ /opt/FlameGraph/stackcollapse-perf.pl < out.stacks \
  | /opt/FlameGraph/flamegraph.pl \
   --color=mem \
   --title="mmap Flame Graph" \
   --countname="calls" > out.svg

上面的原生可执行文件是通过传递 -Dquarkus.native.debug.enabled-Dquarkus.native.additional-build-args=-H:-DeleteLocalSymbols 作为额外的构建标志创建的。

mmap 调用可能出于多种原因发生,但在本文的上下文中,我们感兴趣的是由对象分配触发的 mmap 调用。并非所有对象分配都会触发 mmap 调用。相反,SubstrateVM 中的每个线程在分配第一个对象时都会使用 mmap 分配一个堆块,并且只要同一线程中有空间用于进一步分配对象,它就会使用该堆块。当堆块已满时,线程将请求新的堆块,使用 mmap。这种模式称为线程本地分配。HotSpot 也有类似的功能,但堆块大小是根据多个因素动态计算的,而在 SubstrateVM 中,大小是固定的。在撰写本文时,默认堆块大小为 1MB,但即将进行的更改将使其变为 512KB。

当线程缓存了堆块且有足够的空间容纳对象时,我们将对象分配描述为快速。当线程需要通过 mmap 系统调用请求新的堆块来满足对象分配时,我们将对象分配描述为慢速。慢速分配是这种情况下的关键,因为它们为我们提供了对象分配导致堆块数量增加的大致指示,从而导致 RSS 消耗增加。在 SubstrateVM 中,慢速分配路径的堆栈跟踪包含对 com.oracle.svm.core.genscavenge.ThreadLocalAllocation 类中定义的方法的调用,这些方法在其名称中包含 slowPathNew 前缀。例如,普通对象的 slowPathNewInstance 或数组的 slowPathNewArray

火焰图中的关注区域是包含 ApplicationImpl.doStart() 方法调用的堆栈跟踪,因为该方法负责启动 Quarkus 应用程序。我们想找出这些由 main 线程执行的堆栈跟踪中有多少慢速分配路径。此外,通过查看导致这些慢速分配的堆栈跟踪,我们可以大致了解哪些组件可能分配量很大。如果将火焰图聚焦在该方法上,然后在右上角单击 搜索 并键入 slowPathNew,您就可以观察到哪些 sys_enter_mmap 系统调用与原生堆内存分配有关。

对于 Quarkus 2.7.6.Final,火焰图如下所示。

startup rss startup flamegraph for Quarkus 2.7.6.Final

这里有一张截图,突出显示了包含慢速分配路径的堆栈跟踪。

slow path new allocations for Quarkus 2.7.6.Final

观察上面包含 slowPathNew 调用的堆栈跟踪数量,即 2 个,我们可以说 Quarkus 2.7.6.Final 中的 main 线程分配的堆块大约为 2MB。

对于 Quarkus 2.13.4.Final,火焰图如下所示。

startup rss startup flamegraph for Quarkus 2.13.4.Final

聚焦于同一区域,我们观察到在这种情况下,slowPathNew 堆栈跟踪的数量为 5,因此 main 线程分配的堆块大约为 5MB。

slow path new allocations for Quarkus 2.13.4.Final

这两个 Quarkus 版本之间运行时启动时的对象分配增加,加上 SubstrateVM 中线程本地分配工作方式的特殊性,是导致 RSS 消耗增加的原因。换句话说,尽管 HotSpot 和 SubstrateVM 都经历了更高的分配,但 SubstrateVM 的固定线程本地分配堆块大小使其比 HotSpot 的动态线程本地分配逻辑更明显。

此后,导致额外对象分配的组件得到了改进。通过查看导致慢速分配的堆栈跟踪中出现的组件,并检查这些组件中发生的更新,我们能够检测到导致这些额外分配的更改。在这种情况下,SmallRye 在启动时配置处理的更新导致了回归。

导致慢速对象分配的堆栈跟踪为我们提供了内存使用量增加的组件的近似值。在某些情况下,导致慢速分配的堆栈跟踪是完全有效的,但由于对象分配的非确定性,该堆栈跟踪恰好是导致分配新堆块的原因。但是,如果您在同一区域看到多个堆栈跟踪,那可能是一个很好的提示,表明该区域中的某些内容需要进行调查。

到 Quarkus 版本 2.13.7.Final,启动时的 RSS 消耗已恢复到之前的水平。RSS 回归是由 PR #26802 中的更改引起的,而 PR #29408PR #29842 中的修复将其降低了。

使用 ObjectAllocationInNewTLAB JFR 事件执行分析

随着 GraalVM 新版本在原生模式下实现 越来越多的 JFR 事件,分析 Quarkus 应用程序性能也变得更加容易。例如,最近发布的 GraalVM for JDK 17/20 增加了对 jdk.ObjectAllocationInNewTLAB 事件的支持,该事件将突出显示上述 Quarkus 版本之间的差异。不幸的是,这里测试的 Quarkus 版本与此 GraalVM 版本不兼容,但我们可以尝试使用最新的 Quarkus 版本来看看结果。

首先,我们使用 JFR 支持构建原生 Quarkus 应用程序。

$ ./mvnw package -DskipTests -Dquarkus.native.monitoring=jfr -Dnative

要获取 jdk.ObjectAllocationInNewTLAB 事件,需要一个自定义的 JFC 配置文件。我们使用 jfr configure 来生成它。

$ $JAVA_HOME/bin/jfr configure jdk.ObjectAllocationInNewTLAB#enabled=true --output newtlab.jfc

然后,我们使用必要的 JFR 标志启动原生 Quarkus 可执行文件。

$ getting-started/target/getting-started-1.0.0-SNAPSHOT-runner -XX:+FlightRecorder -XX:StartFlightRecording=settings=newtlab.jfc,filename=recording.jfr -Xmx64m
...
2023-07-21 12:25:33,739 INFO  [io.quarkus] (main) getting-started 1.0.0-SNAPSHOT native (powered by Quarkus 3.2.1.Final) started in 0.019s. Listening on: http://0.0.0.0:8080

在 Quarkus 关闭后,我们可以使用 Adoptium 的 Eclipse Mission Control 来可视化所有 jdk.ObjectAllocationInNewTLAB 事件的火焰图。我们还可以类似地聚焦于 ApplicationImpl.doStart() 方法,以观察从中触发了哪些慢速分配路径。

new tlab events from ApplicationImpl.doStart() method Quarkus 3.2.1.Final

查看火焰图,我们可以为 main 线程计算出 7 个慢速分配路径的堆栈跟踪。这是否是一个问题,或者代码执行是否已从另一个线程转移到 main,将是我们需要进一步探讨并查看是否有回归的地方。

如果您在原生应用程序中遇到内存问题或其他性能问题,请不要犹豫尝试 JFR。Robert Toyonaga 撰写了几篇关于最新 JFR 功能的博文,请在此 了解更多信息。