最近发现线上的某个查询微服务，发生了一个奇怪的问题，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这个工具，可以看到:
基本上从死查询开始的所有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 <<EOF Date: $HUMAN_DATE PID: $PID Signal: $SIGNAL Command: ${EXECUTABLE//!//} SHA256(Executable): $EXE_HASH EOF lsof -p $PID -Pn ) | aws s3 cp - "${S3_KEY}/meta" echo "Uploading tarball" #XXX: which of these files duplicate data already present in the core dump? #XXX: also, if any of these files are useful, should we get the same from each # running thread tar -C /proc/$PID -c \ cgroup \ cmdline \ cpuset \ comm \ environ \ gid_map \ io \ maps \ mountinfo \ sched \ schedstat \ smaps \ stack \ stat \ status \ uid_map \ wchan \ | aws s3 cp - "${S3_KEY}/proc.tar" echo "Uploading core file" echo "You may see 'Aborted (Core Dumped)' printed to the terminal before completion" # If you can't use zstd, consider lz4 instead: it has compression throughput # suitable for streaming uploads. zstd --adapt | aws s3 cp - "${S3_KEY}/core.zst"
