由一次不断GC并耗费过长的时间所想到的工具 - jvmkill与jvmquake

干货满满张哈希

发布于 2021-04-12 14:26:34

8350

发布于 2021-04-12 14:26:34

最近发现线上的某个查询微服务，发生了一个奇怪的问题，GC次数突然变多，GC的时间耗费也变多。并不是一直有这个问题，而是每隔一段时间就会报出来的。

查看jstat -gcutils 10000：有类似于如下的：

S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
0.00 100.00 100.00 100.00  44.56  95.10     21    8.678    11  140.498  149.176
0.00 100.00 100.00 100.00  44.56  95.10     31    8.678    11  140.498  169.176
0.00 100.00 100.00 100.00  44.56  95.10     41    8.678    11  140.498  189.176

查看jmap发现，有很多很多的ByteArrayRow就是jdbc数据返回相关的对象：

 num     #instances         #bytes  class name (module)
-------------------------------------------------------
   1:       6736991      270490848  [B (java.base@11.0.4)
   2:       2154446       51706704  java.lang.String (java.base@11.0.4)
   3:        184135       30913512  [[B (java.base@11.0.4)
   4:          3720       30535872  [C (java.base@11.0.4)
   5:        102716       20543200  业务数据库实体POJO类
   6:        543210       17382720  java.sql.Timestamp (java.sql@11.0.4)
   7:        524288       12582912  org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
   8:         48220        7123584  [Ljava.lang.Object; (java.base@11.0.4)
   9:         71046        6252048  java.lang.reflect.Method (java.base@11.0.4)
  10:        152288        4873216  java.util.concurrent.ConcurrentHashMap$Node (java.base@11.0.4)
  11:        183671        4408104  com.mysql.jdbc.ByteArrayRow
  12:         14721        4056328  [I (java.base@11.0.4)
  13:          1959        3149560  [J (java.base@11.0.4)

推测，可能某个数据库查询语句写的有问题，导致查询范围过大（应该是上面的那个业务类相关的查询）。通过定位，发现，某个定时任务触发一个全扫描的SQL，导致JVM GC压力突然升高，而且不会OutOfMemory。

像这样的问题，定位比较麻烦，最好有个工具。能够关闭这个实例，同时dump出内存占用，用于定位解决问题。

对此，NetFlix不愧是JAVA EE框架的鼻祖。早就有人想到了这个相关的工具。

“死查询”与jvmkill

NetFlix有很多基于JAVA实现的存储，例如Cassandra还有ElasticSearch。这些大部分时间都运行良好。但有时候，某个bug或者设计不当，导致一次全量查询或者是大量查询，使内存耗尽或者陷入不断地GC中。这样，这个实例的请求速度会大幅度下降，这是一个不健康的实例。对于这种由于“死查询”导致不健康的实例，第一步我们想到的就是把它及时的kill掉，省的影响业务性能。jvmkill就可以实现。

jvmkill是一个运用JVM tools Interface的java agent，主要基于ResourceExhausted这个钩子回调，当JVM进入outofmemoryerror：unable to create new native thread状态或者是outofmemoryerror: java heap space状态的话，就会kill掉这个jvm进程。这个工具可以和-XX:HeapDumpOnOutOfMemoryError这个jvm启动参数一起使用，用于在OutofMemory的时候，打印这个堆的内存快照，用于定位问题。

至于如何恢复，我们的集群用的是容器，在发现进程kill掉之后，会启动新的pod（实例）

jvmkill无法解决的场景的完善 - jvmquake

但是，并不是所有的问题都能这样解决。像我们开头提到的这个问题，就不能解决。开头提到的问题只是不断地进行GC，并不会OutOfMemory，像这种问题，jvmkill就无法解决了。

NetFlix用Cassandra举了一个类似的读取全表的例子：

cqlsh> PAGING OFF
Disabled Query paging.
cqlsh> SELECT * FROM large_ks.large_table;
OperationTimedOut: errors={}, last_host=some host
cqlsh> SELECT * FROM large_ks.large_table;
Warning: schema version mismatch detected, which might be caused by DOWN nodes; if this is not the case, check the schema versions of your nodes in system.local and system.peers.
Schema metadata was not refreshed. See log for details.

用JVM工具查看目前的Cassandra实例状态：

$ sudo -u cassandra jstat -gcutil $(pgrep -f Cassandra) 100ms
S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176
0.00 100.00 100.00 100.00  97.96  95.10     21    8.678    11  140.498  149.176

$ grep "stopped" gclog | tail
2019-03-05T02:59:15.111+0000: 1057.680: Total time for which application threads were stopped: 18.0113457 seconds, Stopping threads took: 0.0001798 seconds
2019-03-05T02:59:16.159+0000: 1058.728: Total time for which application threads were stopped: 1.0472826 seconds, Stopping threads took: 0.0001542 seconds
2019-03-05T02:59:40.461+0000: 1083.030: Total time for which application threads were stopped: 24.3016592 seconds, Stopping threads took: 0.0001809 seconds
2019-03-05T03:00:16.263+0000: 1118.832: Total time for which application threads were stopped: 35.8020625 seconds, Stopping threads took: 0.0001307 seconds
2019-03-05T03:00:51.599+0000: 1154.168: Total time for which application threads were stopped: 35.3361231 seconds, Stopping threads took: 0.0001517 seconds
2019-03-05T03:01:09.470+0000: 1172.039: Total time for which application threads were stopped: 17.8703301 seconds, Stopping threads took: 0.0002151 seconds

从GC日志上面可以看出，出现了重复的20秒以上的GC耗时，通过GCViewer这个工具，可以看到: -[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-MeI0fUew-1574674696536)(https://miro.medium.com/max/2400/0*ij4D5X1sHk3EIaMs)]

基本上从死查询开始的所有GC时间都很长很长，而且基本上也恢复不了了。最好对于这个问题，有相应的监控能主动kill掉这个进程。但是，现有的JVM启动参数或者状态位监控，都无法实现。

jvmquake实现思路与解决方案

Netflix的工程师认为，无论负载多高，JVM主要时间应该花在处理业务逻辑上面，而不是GC上面。如果业务占用时间比例持续很低，这个JVM进程需要被kill掉了。于是，他们设计了这样一个模型：GC时间池。当有GC发生时，假设耗费了200ms，则GC池+200ms；业务运行耗费的时间，假设是500ms，会被用于扣除GC时间池，底线是0，不能为负，这里就是扣到了0。这样，如果GC时间与业务时间比值一直大于1:1，那么这个GC时间池会无限增长下去。当到达一定限度的时候，就认为JVM是不健康的了。这就是jvmquake的实现思路。

这个GC时间是如何测定的呢？通过GarbageCollectionStart 和 GarbageCollectionFinish这两个Java Tool Interface

jvmquake包含三个参数：

GC池上限： 如前文所述，。当到达一定限度的时候，就认为JVM是不健康的了，就会采取对应的操作。
业务时间与GC时间的比例： 期望的业务时间与GC时间比，默认是1:1，假设期望是2:1.那么就是GC池=+2GC时间 - 1业务时间。一般，业务时间占比是95%以上（就是19：1）。
采取动作： 对于jvmquake，在向JVM进程发送SIGKILL之前，还需要做一些其他操作来保留现场，用于之后定位原因。

采取什么动作？full dump转向core dump

那么这些究竟是什么操作呢？首先，我们肯定想保留jmap的full dump。可以通过一个线程不断创建大数组导致OOM，从而触发-XX:HeapDumpOnOutOfMemoryError打印full dump。但是，如果发生了好几次kill与重启。那么会有硬盘被写满的风险。最好这个dummp输出能有通道接口，写入到本地磁盘以外的IO中（例如S3）。但是，很可惜，jvm没有。我们可以转向core dump。

通过发送SIGABRT， linux会自动打印core dump。这个core dump的大小，由ulimit -c这个限制控制。如果想不限制，可以通过命令：

ulimit -c unlimited

我们还是想把它上传到S3存储，幸运的是，可以通过kernel.core_pattern sysctl将core dump的输出到一个特定的pipe中（参考linux内核手册，“Piping core dumps to a program”这一章）

coredump_uploader.sh

#!/bin/bash
# Depends on zstd (>1.3.6) and aws-cli
set -o errexit
set -o nounset
set -o pipefail

# Set kernel.core_pattern = | coredump_uploader.sh %P %s %E
PID=$1
shift
SIGNAL=$1
shift
EXECUTABLE=$1
shift

# Set these to appropriate values for your environment
readonly BUCKET=
readonly APP_NAME=
readonly INSTANCE_ID=
readonly COREDUMP_BACKOFF_MINS=60

TARGET_STDERR="/proc/${PID}/fd/2"
if ! exec 2>>"${TARGET_STDERR}" >&2; then
  # Redirect output into the target's stderr, if possible
  exec 2> >(exec 2>&-; logger -t "coredump-uploader-${PID}")
  exec >&2
fi

echo "${0##*/} initiated for PID ${PID}"
mkdir -p /run/coredumps

find /run/coredumps -mmin "+${COREDUMP_BACKOFF_MINS}" -type f -delete
LAST=$(find /run/coredumps -type f -printf "%t\n" | head -n1)
if [ -n "${LAST}" ]; then
   # Back off without creating a file
   echo "Last core dump was at ${LAST}; too soon to upload another."
   exit
fi
mktemp -p /run/coredumps dump.XXXXXXXXXX

MACHINE_DATE=$(date "+%s.%N")
HUMAN_DATE=$(date -d "@${MACHINE_DATE}" '+%Y-%m-%dT%H:%M:%S.%N')
TWO_63=9223372036854775808
REVERSE_DATE=$(($TWO_63 - ${MACHINE_DATE/.})) # overflows in 2230

S3_KEY="s3://${BUCKET}/apps/${APP_NAME}/coredumps/${INSTANCE_ID}/${REVERSE_DATE}_${HUMAN_DATE}"
echo "Uploading to: ${S3_KEY}"

echo "Uploading metadata"
EXE_HASH=$(sha256sum /proc/$PID/exe | cut -d' ' -f1)
(
    cat <