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连接.

诊断错误的正则表达式导致的 StackOverflowError

在生产环境中, 见过很多错误的正则表达式导致的各种错误, 比如: 导致CPU 100%(完整占用一个CPU), 导致StackOverflowError, 导致性能下降很严重. 这里以一个错误的正则表达式导致StackOverflowError 为例子, 看如何诊断并找到根本原因.

案例

我们看到某个应用的错误最近非常多的 StackOverflowError, 并且CPU 使用率明显上升, 下面是我们在错误日志看到的:

st=java.lang.StackOverflowError 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4340) 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347) 
at java.base/java.util.regex.Pattern$GroupHead.match(Pattern.java:4807) 
at java.base/java.util.regex.Pattern$Loop.match(Pattern.java:4944) 
at java.base/java.util.regex.Pattern$GroupTail.match(Pattern.java:4866) 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347) 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347) 
at java.base/java.util.regex.Pattern$GroupHead.match(Pattern.java:4807) 
at java.base/java.util.regex.Pattern$Loop.match(Pattern.java:4944) 
at java.base/java.util.regex.Pattern$GroupTail.match(Pattern.java:4866) 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347) 
at java.base/java.util.regex.Pattern$BmpCharPropertyGreedy.match(Pattern.java:4347)
...

这是截取的部份在日志中的栈, 但是即便日志中的栈有 1024 行, 但是这1024行都是上面最后面5行的重复. 也就是说尽管抛出 StackOverflowError 错误的时候, 打印出最后的1024行栈, 但是这1024 行都是正则表达式处理的栈, 没有我们期望看到的到底是我们的哪段代码调用了这个正则.

问题分析

要想找到这个错误的正则表达式, 我们必须找到我们自己的代码, 如果我是代码开发者, 并且这个应用仅有一处使用正则表达式的地方, 那么很容易就能找到这个正则表达式. 如果做为SRE, 对这个应用代码不熟悉, 可能就要想其它方法了.

如果找到了这个正则表达式, 除非这个正则表达式的错误看起来很明显, 否则, 我们都需要一个被处理的字符串样本, 如何拿到一个样本?

StackOverflowError 栈的深度

  1. 多深的栈会发生 StackOverflowError?
  2. 发生 StackOverflowError 时, 会打印最内层多少层栈?
    我们可以通过命令来看一下(当前JDK是 MAC 上 JDK17):

    java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal -version | grep Stack
      intx CompilerThreadStackSize                  = 1024                                   {pd product} {default}
      intx MaxJavaStackTraceDepth                   = 1024                                      {product} {default}
      bool OmitStackTraceInFastThrow                = true                                      {product} {default}
      bool StackTraceInThrowable                    = true                                      {product} {default}
      intx ThreadStackSize                          = 1024                                   {pd product} {default}
      intx VMThreadStackSize                        = 1024                                   {pd product} {default}
    openjdk version "17.0.4.1" 2022-08-12 LTS

上面各个选项的说明:

  1. CompilerThreadStackSize JVM 编译器的栈大小, 单位是 Kbytes, 所以是栈的大小, 不是深度.
  2. MaxJavaStackTraceDepth 当有异常的时候, 打印的Java 栈的深度的行数, 0 表示所有行, 默认1024行.
  3. OmitStackTraceInFastThrow 如果一个异常抛出太快太多, 那就省略它的栈, 直接打印异常名字. 一般开始还打印栈, 后面就直接打印异常名字了(因为太热, 编译成二进制). 笔者在生产环境见过多次这样的问题, 都是到最开始出错的地方去看原始栈, 或重启它.
  4. StackTraceInThrowable 在 Throwable 抛出时, 带着栈.
  5. ThreadStackSize 线程栈的大小, 单位是 Kbytes, 所以不是深度.
  6. VMThreadStackSize 非 Java 栈的大小, 单位是 Kbytes, 所以不是深度.

所以, 我们可以回答上面的2个问题: 能运行栈的深度是由 ThreadStackSize 决定的, 它的单位是字节, 在上面的 JVM 中, 它最大允许 1024 KB, 而出异常后能打印的栈, 是由 MaxJavaStackTraceDepth 决定的, 它默认只打1024行.

如何找到错误使用正则表达式的代码以及错误的正则表达式?

通过设置 -XX:MaxJavaStackTraceDepth=0 就能打印出所有栈, 那么就能逐级向上找到错误正则.

如何找到一个导致 StackOverflowError 的样本?

在 上面我们自己的代码处 加上 try {} catch (StackOverflowError e) {}, 当捕获着异常的时候, 打印导致出错的样本.

服务延迟变长的思考

最近有人咨询这么一个问题: 他们提供某个服务, 这个服务的耗时偶尔突然变长. 比如平时这个服务的P99的延迟是800毫秒左右, 而最近这个服务的P99延迟已经接近4秒. 它们自己也做了很多功课, 发现延迟开始增加的大概时间就是他们有新客户接入的时间, 所以他们觉得是请求数量增加导致P99延迟变长. 于是他们去问容量规划团队去加机器, 但是容量规划团队看了他们的CPU使用率也不高, 内存使用量也不高, 拒绝了他们的要求. 他们又去查看变慢请求的具体日志, 发现了某些特征的日志: 有些2行日志中间平时应该很短, 但是一旦出问题, 这二行日志中间会有比平时长的多的时间间隙.

下面是一个具体的例子:

06:48:31.28    /api/query/v1/metrics?responseFormat=FLAT
06:48:34.48    Total Attempt #1 for client MyEventClient for AsyncRetrier

可以看到这2行日志中间隔了3.2秒, 而正常情况下, 这2行的中间通常少于10毫秒.

对于这类问题, 通常有哪些解题思路呢?

问题分析

对于延迟变长的问题, 通常我们会主要考虑下面情况:

  1. 服务本身的问题, 比如关键资源的竞争, 锁竞争, JVM 的GC, 新加了大量的耗时逻辑等;
  2. 外部依赖延迟变长, 比如依赖的数据库服务器变慢, 依赖的下游服务变慢, 依赖的网络变慢等;

服务本身问题分析

对于服务本身造成的延迟变长, 也有很多情况.

  1. 假如说服务本身增加了很多耗时的业务逻辑, 这种延迟会体现在所有的请求上面, 而不是偶尔的某些请求.
  2. 假如说是JVM GC 造成的变长, 尤其像这种3秒的延迟, 通常会有更明显的特征:

    1. GC 日志会很好的体现, CPU使用率也会体现.
    2. 凡是经历当时GC的所有请求都会遇到延迟变长的情况.

    而我们看到的实际情况并不符合.

  3. 假如说有锁竞争导致延迟变长, 并且会导致延迟3秒, 那么当时着锁竞争应该很激烈, 会体现在CPU上面, 事实并没有体现.
  4. 假如其它关键资源的竞争导致延迟变长, 那么应该有另外一个线程拥有这种关键资源, 并且占用了3秒, 但我们并不知道有没有这种情况, 所以暂时无法判断. 但是一般对于一个繁忙的应用服务器, 这种情况不会偶尔发生, 会频繁复现.

所以, 如若服务本身的情况, 大多数都会有其它指标体现出来, 也有些情况比较复杂, 比较难判断.

外部依赖问题

通常对于外部依赖, 我们都有2处度量的点:

  1. 在当前服务调用外部服务的点, 这里的延迟包含自己服务IO的调度, 网络延迟, 以及下游真正的延迟.
  2. 在下游服务的入口点, 也就是下游服务自己暴露的延迟信息, 这里仅是下游的服务的延迟.

如果对于#2已经可以看到延迟增加, 那么可以初步定位就是下游服务造成的.
如果下游服务延迟没有增加, 反而#1增加了, 那么可能是网络延迟或者服务器本身IO调度的延迟. 如果是网络延迟造成的, 那么通常网络会影响到所有经过这段网络的服务, 也就是不单单是这个服务受到了影响, 而是很多服务会受到影响. 如果是本身IO调度的问题, 那么通常可能跟大多数从这个网络出入的下游服务都会受到影响, 主要考虑跟有症状的下游相近流量的下游服务.

noise neighbor 影响

如今很多服务都是在 container 里面部署的, 一个宿主机可能部署很多container. 尽管当前应用服务器的CPU使用率很低, 但是那个时间点可能遇到相同宿主机的请它container 在大量使用CPU, 导致当前container 虽然CPU使用率很低, 但是它的进程/线程很难拿到CPU的时间片, 导致延迟变长.

但是这种情况要求延迟变长的应用很多都和 noise neighbor 在一块, 导致经常出这种问题.