JFR 实战之一

自从2016年左右开始干SRE, 就了解到 JFR 是一个非常有用的工具, 尤其在性能调优这一块. 在好几本书和一些文章中都有人提及过, 但是很少见有人用它来解决实际的问题. 可能的原因包括: JFR的很多事件都是JVM本身暴露的稍底层的一些时间, 不熟悉JVM运行机制的话, 很难从这边比较容易的看出问题. JFR 如果用在生产环境是需要付费的.

为了从理论到实践, 这里就在本地开发环境打开JFR, 然后收集一些数据, 然后解读.

设置环境, 开启JFR

本地正好有个 Java 应用: Pycharm, 通过下面的命令可以看到它的一些启动参数:

$ jcmd
60759 jdk.jcmd/sun.tools.jcmd.JCmd
22348 com.intellij.idea.Main

$ jcmd 22348 VM.command_line

$ jcmd 22348 VM.flags -all | grep FlightRecorder
     bool FlightRecorder                           = false                                     {product} {default}
    ccstr FlightRecorderOptions                    =                                           {product} {default}

我们修改 Pycharm 的 JVM 参数. 从 Pycharm 菜单依次点击: Help -> Edit Custom VM Options. 就打开了 ~/Library/Application\ Support/JetBrains/PyCharmCE2023.3/pycharm.vmoptions. 添加下面选项:

-XX:+UnlockCommercialFeatures
-XX:+FlightRecorder

上面的修改类似于 java -XX:+UnlockCommercialFeatures -XX:+FlightRecorder MyApp

重启 Pycharm, 我们再次检查它的参数:

jcmd 62236 VM.flags -all | grep FlightRecorder
     bool FlightRecorder                           = true                                      {product} {command line}
    ccstr FlightRecorderOptions                    =                                           {product} {default}

收集数据

上面的-XX:+FlightRecorder 选项只是说明我们打开了 JFR 的开关, 真正的收集事件并未开始. 通常我们可以通过 jcmd 命令行或者一些GUI工具(JConsole, Java Mission Control等)来开始收集.

通过运行 jcmd 命令, 我们可以看到有关 JFR 的一些命令, 然后通过 help 能看到对应子命令的更多内容:

$ jcmd <pid> help | grep JFR
JFR.check
JFR.configure
JFR.dump
JFR.start
JFR.stop

$ jcmd 62236 help JFR.start
   ... 可以看到很多参数省略 ...

通过如下的命令, 我们可以启动收集:

$ jcmd 62236 JFR.start name=sample1,filename=/tmp/sample1.jfr,during=1m
62236:
Started recording 1. No limit specified, using maxsize=250MB as default.

Use jcmd 62236 JFR.dump name=sample1,filename=/tmp/sample1.jfr,during=1m filename=FILEPATH to copy recording data to file.

查看这个收集任务 并把数据保存到文件

$ jcmd 62236 JFR.check
62236:
Recording 1: name=sample1,filename=/tmp/sample1.jfr,during=1m maxsize=250.0MB (running)

jcmd 62236 JFR.dump name=sample1,filename=/tmp/sample1.jfr,during=1m filename=/tmp/sample1.jfr
62236:
Dumped recording "sample1,filename=/tmp/sample1.jfr,during=1m", 6.2 MB written to:

/private/tmp/sample1.jfr

关于这几个子命令的更多信息: https://docs.oracle.com/javacomponents/jmc-5-4/jfr-runtime-guide/comline.htm#JFRUH188

解读数据

解读数据需要 Java Mission Control (JMC), 下载页面: https://www.oracle.com/java/technologies/javase/products-jmc8-downloads.html

启动 JMC, 然后打开刚才的文件.
jmc.png

事件类型

JFR 收集3类数据类型:

  1. 持续事件: 需要一段时间才会发生,并在完成时记录。你可以设置持续事件的阈值,以便只记录持续时间超过指定时间段的事件。
  2. 瞬时事件: 立即发生,并立即记录。
  3. 样本事件: 以固定间隔记录,以提供系统活动的样本。你可以配置采样发生的频率。

关于 Java GC 里面的PLAB

之前有篇文章提到过 TALB (Thread-Local Allocation Buffers), 与之类似的概念在年轻代 promote 到 survivor 和 old generation 的时候, 也有 PLAB.

什么是 PLAB

PLAB 是 Promotion Local Allocation Buffers 的缩写, 是 Java 垃圾回收相关的概念. heap 里面通常把heap 分为年轻代和老年代,年轻代又细分为 Eden 区域和 2个 survivor 区域. 当把 Eden 区域的对象 promote 到老年代的时候, 我们称之为 Promotion. 但是在 promote 到老年代之前, 根据设置参数的不同, 可能会现在2个 survivor 区域来回复制几次.

从 Eden 区域复制到 survivor 区域或者 promote 到老年代都是 GC 线程做的事情, 这个时候是 CPU 密集型操作. 并且复制到的目的区域是各个GC 线程同样的目的区域. 这个时候就会出现竞争, 竞争就会出现锁.

为了避免锁竞争, 就要采用分块的概念, 也就是给每个做GC 的线程独自分配一块区域, 是它自己独享的目的区域, 这样就能避免竞争. 于是就有了 PLAB 的概念.

与 PLAB 相关的参数

这是基于 JDK 17 的与 PLAB 相关的参数:

java -XX:+PrintFlagsFinal -version | grep PLAB
   size_t OldPLABSize                              = 1024                                      {product} {default}
    uintx PLABWeight                               = 75                                        {product} {default}
     bool ResizePLAB                               = true                                      {product} {default}
    uintx TargetPLABWastePct                       = 10                                        {product} {default}
   size_t YoungPLABSize                            = 4096                                      {product} {default}

PLAB 与 NUMA

这篇文章讨论了 G1 在 NUMA 情况下如何 promote 对象到老年代的时候, 处理 NUMA 内存相关的问题.
https://sangheon.github.io/2020/11/03/g1-numa.html

PLAB 在 CMS 和 G1 GC 的使用

PLAB 参数的相关概念

0.1 - 诊断之前

在开始诊断之前, 我们通常要确定几件事情, 以帮助我们诊断过程更有效和有针对性.

确认对应的 Java 程序在运行.

有时有人报告说某个程序运行不正常, 我们去查看各种指标和日志, 却找不到相关信息, 各种查找以后发现找错了机器,或者对应的程序其实已经退出了. 所以在线诊断一定要先确定要诊断的程序是否正在运行.

有时候我们登录了某台机器, 却无法查看到对应的Java 程序在运行, 可能是我们权限不够, 又或者是在不同的 pod/container 里面. 所以在开始诊断之前, 这些信息最好确认好, 否则会浪费时间.

比如下面的例子中, 我们使用 jps 命令只能看到当时正在运行的 jps 命令本身, 看不到其它 Java 在运行程序. 但是但我们使用 pgrep 命令, 或者 ps 命令的时候, 却能看到这些在 Docker container 里面运行的 Java 程序.

supra@suprabox:~$ jps
3769076 Jps

supra@suprabox:~$ pgrep java
3567
3780
4535

supra@suprabox:~$ ps aux | grep java
7474        3567  0.8  1.8 10073680 308672 ?     Sl   Jan27 511:09 /opt/java/openjdk/bin/java -cp /var/lib/neo4j/plugins/*:/var/lib/neo4j/conf/*:/var/lib/neo4j/lib/* -XX:+UseG1GC -XX:-OmitStackTraceInFastThrow -XX:+AlwaysPreTouch -XX:+UnlockExperimentalVMOptions -XX:+TrustFinalNonStaticFields --console-mode
supra       3780  9.1  9.6 7020176 1561912 ?     Sl   Jan27 5667:41 /usr/share/elasticsearch/jdk/bin/java -Xshare:auto -Des.networkaddress.cache.ttl=60 -Des.networkaddress.cache.negative.ttl=10 -Dio.netty.noUnsafe=true
999         4535  0.1 24.0 8232288 3913624 ?     Ssl  Jan27 104:44 /usr/local/openjdk-8/bin/java -Dlog4j.configuration=file:/opt/janusgraph/conf/log4j-server.properties -Xms4096m -Xmx4096m -javaagent:/opt/janusgraph/lib/jamm-0.3.0.jar

确认 Java 的版本

尽管 Java 会向前兼容, 但不同的 Java 发行版本, 会有不同的默认行为和不同的参数, 确认版本, 帮助我们在后面的诊断中判断某种症状是不是合理.

比如, 对于上面结果中的3个 Java 程序, 它们都运行在 Docker container 中, 我们查看他们的 Java 版本, 发现它们分别都是使用了不同版本的 Java.

supra@suprabox:~$ sudo nsenter -t 3567 -a /opt/java/openjdk/bin/java -version
[sudo] password for supra:
openjdk version "17.0.5" 2022-10-18
OpenJDK Runtime Environment Temurin-17.0.5+8 (build 17.0.5+8)
OpenJDK 64-Bit Server VM Temurin-17.0.5+8 (build 17.0.5+8, mixed mode, sharing)

supra@suprabox:~$ sudo nsenter -t 3780 -a /usr/share/elasticsearch/jdk/bin/java  -version
openjdk version "17.0.1" 2021-10-19
OpenJDK Runtime Environment Temurin-17.0.1+12 (build 17.0.1+12)
OpenJDK 64-Bit Server VM Temurin-17.0.1+12 (build 17.0.1+12, mixed mode, sharing)

supra@suprabox:~$ sudo nsenter -t 4535 -a /usr/local/openjdk-8/bin/java -version
openjdk version "1.8.0_332"
OpenJDK Runtime Environment (build 1.8.0_332-b09)
OpenJDK 64-Bit Server VM (build 25.332-b09, mixed mode)

不同版本的Java 可能对应不同的默认参数, 我们可以通过下面的命令来查看这些默认参数的名字,及默认值:

supra@suprabox:~$ java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -version
[Global flags]
      int AVX3Threshold                            = 4096                              {ARCH diagnostic} {default}
      int ActiveProcessorCount                     = -1                                        {product} {default}
     intx AliasLevel                               = 3                                      {C2 product} {default}
   size_t TLABSize                                 = 0                                         {product} {default}
                                            ... 省略更多 ... 

这个列表很长, 大多数你可能都用不到, 但是某些值对于以后诊断某些问题的细节很有用. 第一列是类型, 第二列是参数的名字, 第三列显示默认值, 第四列里面的不同值表示不同的意思, 比如是否跟某些平台架构想管, 是不是诊断用的参数, 是不是某个特定的编译器才有的参数等, 最后的 {default} 表示是不是一定有默认值.

确认启动命令及参数

有些参数的不设置是有默认值的, 比如初始堆大小, 有些值是根据不同的平台及硬件特性在启动时根据算法选择的, 有些是用户在启动命令参数设置的, 有些虽然可能有默认值或启动设置值, 但是运行时是可以改的. 所以我们要了解这些启动参数是不是有默认值, 默认值是如何设置或计算的, 是不是用户设置了它的值, 它的值在启动后是不是被改动了.

Distroless image 使用经验

最近开始使用 GoogleContainerTools 的 distroless image, 但是遇到了一些问题, 这里记录一下.

distoless image 是啥?

https://github.com/GoogleContainerTools/distroless
GoogleContainer Distroless镜像是一种用于容器化应用程序的轻量级基础镜像,它旨在最小化容器的攻击面和大小。它由Google开发并维护,专为在Kubernetes等容器编排平台上部署的应用程序而设计。

Distroless镜像的一些优点包括:

  1. 最小化攻击面:Distroless镜像只包含应用程序运行所需的最小运行时组件和依赖项,因此减少了潜在的安全风险。它不包含操作系统工具或其他不必要的软件包,使得容器更加安全。
  2. 减小镜像大小:由于Distroless镜像只包含应用程序运行所需的最小组件,因此它们的大小相比包含完整操作系统的基础镜像更小。这可以减少容器的下载时间和存储空间。
  3. 简化部署和维护:Distroless镜像提供了一个简化的部署流程,因为它们不需要管理操作系统的配置或更新。这使得容器化应用程序的部署和维护更加简单和高效。
  4. 与容器编排平台集成:Distroless镜像与Kubernetes等容器编排平台无缝集成,可以轻松地部署和管理大规模的容器化应用程序。

总的来说,Distroless镜像提供了一种安全、高效和简化的方式来容器化应用程序,使开发人员能够更专注于应用程序的开发和部署,而无需担心底层基础设施的细节。

注意: 它默认连shell 都没有, 只有后缀加上 :debug 才有 busybox 的shell. 也没有包管理器, 所以不能安装任何东西.

Dockerfile RUN, CMD, and ENTRYPOINT 指令的 shell 和 exec 形式

https://docs.docker.com/reference/dockerfile/#shell-and-exec-form

RUN, CMD, and ENTRYPOINT 有2种形式: shell 和 exec 形式.
shell 形式: 用字符串形式, 会被shell解释, 例如: RUN echo $HOME
exec 形式: 用数组形式, 不会被shell解释, 例如: RUN ["echo", "$HOME"]

Shell形式依赖于容器内的shell解释器,会增加一定的额外开销,因为每个命令都需要被shell解释器处理。
Exec形式直接将命令传递给Docker守护进程,避免了额外的shell解释器,因此更加高效。

遇到的问题

  1. 由于distroless没有shell, 所以不能用shell形式, 只能用exec形式. 若要使用shell, 要么使用 :debug 版本, 要么自己 copy busybox 到镜像里.
  2. 由于 python 命令和 pip 命令要使用 PYTHONPATH 环境变量, 所以要用shell形式, 但是distroless没有shell, 所以只能用exec形式, 所以只能用 python -mpip install 的形式. 但是这样找不到安装的模块, 要么使用 busybox shell, 要么在 python 代码一开始使用 sys.path 设置需要依赖的文件.
  3. python 版本差异. 由于不能安装东西, 所以只能通过build 环境container安装, 比如安装的东西和最后使用的 distroless image 里面的系统是不是兼容, 要考虑.

诊断 SSL 连接过多造成的CPU过载性能下降

有同事反映他们的应用最近经常出现: CPU 将近100%, tomcat busy thread 达到最大阈值, GC 花费的时间也增加, 最终处理请求变慢. 现象就是下面这种:
state.png

症状分析

GC 其实并不太高, 也就是15%以下, 所以它基本是结果, 不是原因. latency 过高也是结果, tomcat busy thread 变高也是结果, 因为处理变慢, 所以 busy thread 增加. 所以根本原因是CPU 过高.

为什么CPU 很高?

要看CPU都花在哪里了, 所以要对应用做 profiling, 于是使用 async-profiler 做 profiling. 结果如下图:
flame.png

从图上看到, 应该是新建连接太多, 每个都要SSL, 所以耗时, 变慢.

为啥连接这么多

最近流量增加, 每个都要调用下游, 但是没有使用连接池, 导致每个下游调用都需要新建一个SSL连接.