分类 Java 相关 下的文章

关于 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 参数的相关概念

诊断 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 在一块, 导致经常出这种问题.

Java 为什么我要的锁不见了

线上遇到问题: 有些 Tomcat 线程卡住了, 卡住的越来越多, 重启虽然能暂时解决, 但不是长期解决办法, 如下图:
TomcatBusyThread.png

确定卡住的线程

随机找一个症状还在的服务器, 获取 thread dump, 看到如下卡住的线程 (截取部分):

"MyTaskExecutor-127" #407 daemon prio=5 os_prio=0 tid=0x00007ff6d0019000 nid=0x1da waiting on condition [0x00007ff4159d7000]
   java.lang.Thread.State: WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x000000075e438328> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:837)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:872)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1202)
    at java.util.concurrent.locks.ReentrantLock$NonfairSync.lock(ReentrantLock.java:213)
    at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:290)
    at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:951)
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
    at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
    - locked <0x000000075e5b2488> (a java.io.BufferedInputStream)
    at sun.net.www.MeteredStream.read(MeteredStream.java:134)
    - locked <0x000000075e5b4400> (a sun.net.www.http.KeepAliveStream)
    at java.io.FilterInputStream.read(FilterInputStream.java:133)
    at sun.net.www.protocol.http.HttpURLConnection$HttpInputStream.read(HttpURLConnection.java:3471)

可以看出这是一个使用 HTTPS 访问外部请求的操作, 现在卡在了 SSLSocketImpl$AppInputStream.read() 上面, 现在它需要一把锁.

环境信息

Open JDK 1.8.362. 为什么要强调 JDK 版本, 后面会看到JDK涉及到这块的代码改动量非常大, 每个版本代码都不一样.

初步分析

一开始认为是没有设置 read timeout, 导致一直死等. 但是看了应用程序配置, 发现是设置的, 查看heapd dump 里面, 却是也是设置的. 如下图:
timeout.png

为什么设置了 connect 和 read timeout 还死等

根据这个栈可以看出, 连接已经建立(新建或者使用KeepLiveCache里面的), 所以, connect timeout 阶段已经过了, 不管用了.
同时, read time 是在使用 poll() 或者在它的外层 c代码 Java_java_net_SocketInputStream 里面才会计算 read timeout, 所以这里还没到.

这个线程等的锁被谁占用

通过 thread dump 很容易可以看到, 这个锁被下面的线程占着.

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007ff8508d3000 nid=0x26 in Object.wait() [0x00007ff80f427000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000007570016f8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
    - locked <0x00000007570016f8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:188)

   Locked ownable synchronizers:
    - <0x000000075e438328> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e438410> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e613df8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e6682c0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e6a3e90> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e6b4070> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075e6c51f8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075ee84098> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000075f636998> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x00000007610a3e08> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x0000000766af21d0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x00000007759c8fd8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078c1bed50> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078d6fb888> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078e2b8ff0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078f448fc8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078f592e50> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078f5a9430> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
    - <0x000000078f5bed40> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

从上面的信息中看到, 这个Finalizer 线程的 Locked ownable synchronizers部分看, 它占有了很多锁. 其中第一个就是我们之前线程正想要获取的锁.

那么这个 Finalizer 在干嘛?

从上面的栈信息, 结合具体的源代码, 可以看到这个 Finalizer 线程其实在等下一个需要 finalize() 方法的对象. 并且当前没有在排队的对象(从heap dump)可以看到:
lock.png

矛盾的现象

这个线程拥有了这把锁(其实它拥有很多把锁, 从上面Locked ownable synchronizers可以看到), 却没有在使用这把锁做事情, 反而现在没有任何事情在做. 那么它就没有可能释放这把锁. 也就是说, 它曾经获得了这把锁, 但是没办法释放这把锁.

那么任何在等这把锁的对象, 都面临着永远等不来的情况.

为什么会造成这种情况

从现在的数据来看, 这种情况发生的几率很小, 没几天才能发生一次. 从已有的数据看, 很有可能是 Finalizer 线程在执行 sun.security.ssl.SSLSocketImplfinalize() 方法的时候, 获得了这把锁, 然而却没释放.

于是去查看这个版本的sun.security.ssl.SSLSocketImpl的源代码, 发现几乎每处使用这个锁的地方都是 try{}finally{} 方式, 在 finally{} 代码块里去释放的锁. 所以正常执行完不可能不释放.

唯一的可能性就是: finalize() 方法没有正常执行完. 在获得锁还没有释放锁的位置, finalize() 方法被中断了. 在JDK 里面, 根本不保证 finalize() 一定被执行, 什么时候被执行, 以及是不是执行完. 所以在 JDK 9 之后 finalize() 就被 deprecated 了.

思考

如果这个 sun.security.ssl.SSLSocketImpl 已经被开始执行 finalize() 方法, 那么它在某个时间点, 已经被 JVM GC 判定为不可达. 那么肯定有一种神秘的力量把它从死神哪里拉回来了. 并且现在正在被另外一个线程使用.
当一个 AbstractOwnableSynchronizer 的锁被一个线程使用的时候, 它会记录拥有锁的线程名字到它的 exclusiveOwnerThread 字段. 从heap dump, 我们可以证实这个锁也是被 Finalizer 拥有.
lock2.png
这里的线程是 Finalizer, state 是1, 表示这个 ReentrantLock$NonfairSync 被进入一次.

是哪个神秘的力量救活了它?