一次关于生产环境服务无故宕机的排查过程

故事的开始

这个故事是在一年之前，当时我们的系统运行在客户的k8s环境上。然后很神奇的是每个月底我们都会服务宕机，当然我们开启了多个实例。当时的容器线条就像心跳图一样（或许有些描述的不太准确，我没有找到当时那个像心电图一样的容器资源监控图）。

第一次的排查

当时我们还是很有信心去解决这个问题的。由于每个月的月底都是业务使用的高峰时段，也就是说，从表象上来看，qps一高，容器就挂。

业务日志排查

第一时间，我自然查看了我们的业务日志。这很合理，毕竟当时我觉得大概率是OOM了，可是神奇的现象出现了，业务没有任何报错。如下图（原始日志没有去找了，但是大致就是这样）

可以很明显的看到，3s前业务还在正常输出，3s后就开始重启了。没有OOM，没有哪怕任何业务报错，就这么灵异的重启了。

GC排查

在业务日志排查无果的情况下，我们转头查看了GC日志。当时的JAVA的配置，并不优雅，于是我们输出了GC过程，用于定位。
确实由于当时配置的不合理性，我们发现了Full GC，在调整了XMS与XMX之后，后续并没有发生Full GC。
虽然没有定位到直接问题，但是我认为这件事情应该告一段落了，因为容器的宕机确实也是偶发现象。

但是，命运总是爱开玩笑，仅仅一周不到，容器接连宕机，客户满意度极具下降。客户IT部门的Zabbix每次都会监控到我们的服务异常抖动，然后会发邮件给我，当时就觉得很烦。
而这是当时GC日志的输出（我随手掏了一个k8s上3月份的GC日志）：

{Heap before GC invocations=385 (full 2):
garbage-first heap   total 27262976K, used 24909326K [0x0000000160800000, 0x0000000160c0d000, 0x00000007e0800000)
region size 4096K, 5121 young (20975616K), 51 survivors (208896K)
Metaspace       used 217462K, capacity 254752K, committed 275072K, reserved 1275904K
class space    used 24752K, capacity 38227K, committed 47744K, reserved 1048576K
2024-03-13T18:52:10.781+0800: 440420.560: [GC pause (GCLocker Initiated GC) (young)
 Desired survivor size 1342177280 bytes, new threshold 5 (max 5)
- age   1:  117000376 bytes,  117000376 total
- age   2:   20296144 bytes,  137296520 total
 - age   3:   11908392 bytes,  149204912 total
 - age   4:   26488920 bytes,  175693832 total
 - age   5:   25737792 bytes,  201431624 total
2024-03-13T18:52:11.040+0800: 440420.818: [SoftReference, 0 refs, 0.0000523 secs]2024-03-13T18:52:11.040+0800: 440420.818: [WeakReference, 199 refs, 0.0000331 secs]2024-03-13T18:52:11.040+0800: 440420.818: [FinalReference, 2295 refs, 0.0030429 secs]2024-03-13T18:52:11.043+0800: 440420.821: [PhantomReference, 0 refs, 0 refs, 0.0000055 secs]2024-03-13T18:52:11.043+0800: 440420.821: [JNI Weak Reference, 0.0007846 secs] (to-space exhausted), 0.7369998 secs]
[Parallel Time: 250.3 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 440420567.7, Avg: 440420567.7, Max: 440420567.8, Diff: 0.1]
[Ext Root Scanning (ms): Min: 1.4, Avg: 4.8, Max: 18.0, Diff: 16.6, Sum: 38.7]
[Update RS (ms): Min: 4.3, Avg: 17.0, Max: 20.6, Diff: 16.3, Sum: 136.3]
[Processed Buffers: Min: 48, Avg: 179.4, Max: 244, Diff: 196, Sum: 1435]
[Scan RS (ms): Min: 1.3, Avg: 1.4, Max: 1.5, Diff: 0.2, Sum: 11.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 226.5, Avg: 226.8, Max: 227.7, Diff: 1.2, Sum: 1814.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.6]
[GC Worker Total (ms): Min: 250.1, Avg: 250.2, Max: 250.2, Diff: 0.2, Sum: 2001.2]
[GC Worker End (ms): Min: 440420817.9, Avg: 440420817.9, Max: 440420817.9, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 1.8 ms]
[Other: 484.9 ms]
[Evacuation Failure: 463.0 ms]
[Choose CSet: 0.1 ms]
 [Ref Proc: 4.0 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 6.9 ms]
[Humongous Reclaim: 5.5 ms]
[Free CSet: 4.1 ms]
[Eden: 20280.0M(20276.0M)->0.0B(20340.0M) Survivors: 204.0M->140.0M Heap: 24327.5M(26624.0M)->5841.5M(26624.0M)]
Heap after GC invocations=386 (full 2):
garbage-first heap   total 27262976K, used 5981738K [0x0000000160800000, 0x0000000160c0d000, 0x00000007e0800000)
region size 4096K, 35 young (143360K), 35 survivors (143360K)
Metaspace       used 217462K, capacity 254752K, committed 275072K, reserved 1275904K
class space    used 24752K, capacity 38227K, committed 47744K, reserved 1048576K
}
[Times: user=4.17 sys=0.28, real=0.74 secs] 

本次GC其实是有问题的，具体分析一下：
1.本次主要是G1垃圾收集器的Young GC
2.之前发生了两次fullGC，本次是第385次GC
3.total 27262976K, used 24909326K：垃圾回收开始前，整个堆的大小为27262MB，使用了24909MB。region size 4096K：堆的分区（Region）大小为4MB。5121 young (20975616K)：年轻代有5121个Region，总共大约占用了20975MB。51 survivors (208896K)：Survivor区有51个Region，占用约208MB。
4.[Evacuation Failure: 463.0 ms]，意味着Survivor区或者老年代空间不足以存放所有从年轻代复制出来的对象。由于此失败，GC时间显著延长。
5.Heap After GC：total 27262976K, used 5981738K：垃圾回收后，堆的总大小不变（27262MB），但使用量大幅减少，降至5981MB。
6.最后的时间是 [Times: user=4.17 sys=0.28, real=0.74 secs]，明显高于一般GC时间
这里需要注意一个我之前一直理解错的点：
GC的时候，容器的总内存使用量不会显著减少，但是内存的碎片化会减少，同时腾出更多的连续内存空间。因为GC本质上是内存优化算法，为了连续的内存。
当然除了Full GC且涉及堆压缩，会减少整体容器的内存，不过生产环境你不会希望有full GC的

优化策略

针对于刚刚的GC日志，是有一些调整策略的
增加堆内存空间（避免Evacuation Failure）
增加年轻代大小（避免频繁yong gc）
调整晋升到老年代的阈值（-XX:MaxTenuringThreshold 默认16次）
调整xms与xmx（配置合理的初始和最大堆大小，我当时设置了一致的大小）

关于xms与xmx

1. -Xms与-Xmx一致的场景
   适用场景
   • 生产环境：生产环境通常需要应用运行的稳定性和性能。设置相同的Xms和Xmx可以避免JVM在运行过程中不断调整堆的大小，减少性能波动。
   • 长生命周期的应用：如果应用在长时间运行过程中内存需求稳定，并且你预估应用需要使用较大的内存块，那么设置Xms等于Xmx会更合适。
   • 避免频繁的堆扩展和收缩：当应用的内存需求变化较少，或是频繁调整堆大小会影响性能时，一致的Xms和Xmx可以避免堆动态扩展/收缩带来的CPU和GC开销。
   优点
   • 稳定的内存使用，无需JVM在运行时重新分配内存，减少性能波动。
   • 避免应用在堆扩展或收缩过程中触发的Full GC。
   示例场景
   • 高并发服务：如电商、金融系统、在线服务等，需要长时间维持稳定的服务。
   • 大数据处理：如批处理、大规模数据集处理系统，其内存需求较为稳定，且需要处理大块数据。

2.-Xms与-Xmx不一致的场景
适用场景
• 开发和测试环境：开发和测试环境下，应用的内存需求可能会有波动，但你不需要为内存分配太多资源。因此，可以设置较小的Xms，以便JVM根据实际需求进行动态扩展。
• 内存需求有明显波动：如果应用的内存需求在不同负载情况下变化明显，如启动时内存占用较少，但在运行过程中占用逐步增加，则可以设置Xms较小，Xmx较大，以应对内存需求的动态变化。
• 节省内存资源：在内存资源有限的环境中（如容器化部署、云环境），将Xms设置较小，以便根据实际负载动态调整内存使用，避免浪费资源。

优点
• 灵活性：能够根据负载动态调整内存分配，特别是在初始阶段内存需求较少的应用中。
• 节省资源：在初始阶段，系统不会分配大量内存，从而节省系统资源。
示例场景
• 微服务：内存使用量随请求量变化较大，或者依赖外部服务的应用，其初始内存使用较少。
• 定时任务：不需要持续占用大量内存的应用，内存使用随着任务进行而增加。

连接池优化

在GC优化完成之后，我们把目标转到了数据库连接池上。
调整了最大连接数（常见的建议是设置为 CPU 核心数 x 2 + 1，并视业务实际并发量进行调整），最小连接数（以根据系统的最低负载需求来设置，一般建议设置为 5-10 个），连接等待超时，空闲连接检测与回收等
然后这里需要说明的是，数据库不归我们管，我通过navicat等客户端查到的数据库连接池，好像只有几百（客户PIN跳板机恰巧迁移，现在看不了）

总结与后续

第一次的调整，我们整体查看业务日志，分析内存gc情况，调整数据库连接池。但是没啥显著效果，我们隐隐约约觉得是他们k8s有问题，这里声明一下客户不是使用的原生k8s，而是基于k8s的RainBond封装。于是我们进行了第一次三方会谈。
当时我们有看到了这样k8s重启分析文档：
总的来说感觉是客户自己机器的问题。

第一次三方会谈

我们拉上了客户的IT，客户的k8s的RainBond服务商。
但是苦于没有直观的证据，客户这边给出的答复就是整个公司用的都是我们的系统，不会有问题。这其实和技术层面没有半毛钱关系，完全是定责的问题，整个过程极其漫长和痛苦。我们先后派出区域开发，产研，交付总监等（很明显能看出，之前是技术，后面就是扯皮了），但是效果依旧不大。
于是我们采用了一些其他的兜底方案。

客户方的操作

客户需要检测我们的服务器状态，于是增加了zabbix，增加了Prometheus对我们的业务进行了抽取，将整体服务器状态抽取到Grafana
当然只是监控和预警。

鬼鬼祟祟的兜底方案1.0

由于某些不可抗力，以及沟通的障碍性，我们采用了第一版本的兜底方案。
1.我们将服务器pod增加到了6台，每天pod的内存调整到了容器允许的最大值（32G）
2.我们去除了健康检测机制（因为一旦检测失败，就开始不停的重启机器）
3.增加了定时任务，每天凌晨手工重启服务，进行手工释放内存
4.向客户申请了服务器资源，准备脱离RainBond平台进行部署

平台迁移

经过多次协商之后，我们申请到了一堆的机器，进行安装部署我们新的环境。（额外提一嘴，由于与客户关系太僵硬了，我最一开始出的docker-swarm部署方案被驳回了）

预兆

部署完成之后，我发现有个服务系统同样宕机了，但是后面发现是因为这台机器内存过小，在走计划任务之后，oom自己宕机了。于是和客户协商之后，我下线了这个机器。

一次惊险的发现

最终部署完了，验证之后，有天客户告诉我，服务不响应了。我紧急上线进行了排查，查询到了第一次服务假死现象。我有8台主业务服务，nginx配置了集群，但是路由到某台机器之后，服务无返回。
最终我处理完了这个问题，重启了这个服务。然后我惊讶的发现，我有几台服务器的容器的up time是在几小时前。
我当时就慌了，我一下子就想到我是不是错怪RainBond平台，我们并没用真正意义上解决掉这个问题。

鬼鬼祟祟的兜底方案2.0

基于这样容器无故宕机的事情，我第一时间向上汇报了情况。不过由于之前的反复和客户的沟通无果，加上每次协调产品委员会都很耗时。我们第一时间进行了回避这样的问题。
于是，这就是2.0的鬼鬼祟祟兜底方案
具体方案依据就是：我不相信同一时间所有业务服务都挂了。只要nginx实现，自动下线和故障恢复。那么在同一时间，哪怕我的业务服务，挂了一台两台，无所谓，整体业务是可以使用的。
nginx配置：

`` upstream webapi {
``             server 172.25.32.94:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.95:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.96:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.97:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.98:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.99:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.209:8080 max_fails=10 fail_timeout=5m;
``             server 172.25.32.210:8080 max_fails=10 fail_timeout=5m;
``         }
`` 
`` location /api/ {
``             proxy_pass http://webapi;
``             proxy_set_header   X-Real-IP        $remote_addr;
``             proxy_set_header   X-Forwarded-For  $proxy_add_x_forwarded_for;
``             proxy_set_header X-Forwarded-Proto $scheme;
`` 
``             client_max_body_size 200m;
``             proxy_read_timeout  600s;
``             proxy_connect_timeout 10s;
``             proxy_send_timeout 600s;
``             proxy_next_upstream error timeout http_500 http_502 http_503 http_504;
``         }

解释一下：upstream就是我的业务服务集群，考虑到服务重启大概2-3分钟，我这边设置了下线的时间是5m。

1. max_fails=10：指定Nginx允许该服务器发生最大失败次数为10次。在超过这个次数时，Nginx会将该服务器标记为“不可用”。
2. fail_timeout=5m：指定当服务器连续失败超过 max_fails 次之后，服务器将在 5 分钟内被认为不可用。之后Nginx会尝试重新将其加入可用服务器池。
   3.检测的失败实例：error timeout http_500 http_502 http_503 http_504

这里就实现了检测服务失败，并且下线五分钟，五分钟后才会上线。当然如果只是服务宕机重启，那么需要在docker-compose中配置 restart：always

超时问题

超时是一个在生产环境中很常见的问题，接口返回的rt过长，导致504报错。
但是这是两个问题，第一层客户端的nginx超时，是经过网关的，而这个网关一般是客户的运维it处理的。在这种情况下，你服务器上配置的nginx超时时间毫无作用。
第二层就是nginx的readtimeout，connectionTimeOut之类，当然区分的方式很简单，在服务器上curl -v就行。不过这些只是告诉你超时问题表象处理问题，正常的接口还是需要去检查为什么慢，慢在哪里。（后面有空再看要不要再出文档吧，关于代码优化，接口性能分析，代码结构设置等等）

线上宕机问题处理2

这个2表示了我在本周内其实处理了两次了生产环境宕机问题，嗯，两次。
第一次是因为服务器假死，第二次是因为客户的数据库挂了。

服务监控：

这次由于物理机器在我们的手上，我们进行了一次系统级别的查询
使用命令 dmesg -T
然后我发现，有发生了OOM，系统日志的oom，于是他kill到了我的业务服务，基于此，我们初步定位到了问题产生的原因
于是我们进一步的做了筛选
dmesg -T | grep kill

GC的二次调优

我当时物理机器是32G，部署了两个服务，一个20G，一个8G，xmx与xms配置的一致。不过按照系统的日志来看，应该属于内存不足导致linux杀死最大占用内存的线程，所以我进行了整体的调整。

JAVA_OPTS=-Xms8g -Xmx16g -Xss1M -XX:MetaspaceSize=512m -XX:MaxMetaspaceSize=512m -XX:+DisableExplicitGC -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -Xloggc:/cloudpivot/program/backEnd/webapi/logs/gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M -XX:+UseCGroupMemoryLimitForHeap -XX:+HeapDumpOnOutOfMemoryError -XX:NewRatio=1

这里的处理由以下几点：
xms 从20g 到8g 减少内存占用，
xmx从20G到16G 降低webapi对于整体线程的最大占用内存
xms xmx的联合调整，降低了频繁yong gc的频次（GC日志中，yong gc特别频繁）
增加了 Xloggc: -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles -XX:GCLogFileSize 增加了GC日志的转播过程，可以记录服务器之前的gc日志（避免服务器重启后，之前GC日志丢失的情况）
-XX:NewRatio=1 新生代 老年代 比例调整是1：1，通过GC日志发现新生代占用大量空间，老年代则有资源浪费。因此调整成1：1，合理化分配内存资源

起到的预期效果：GC输出服务重启前的日志，JVM合理化、高效运用内存
整体这几天的监控是没有发现，服务无故重启。

jstack输出定位

恰巧在服务故障之后的，第二天服务又不可用了，此时我将jstack进行了输出和分析。

由于是生产环境的问题，所以当时记录的比较散。
大致的操作步骤
1.docker exec -it 容器内部
2.jps -lv 罗列java线程
3.查看线程id ps -ef|grep java
4.jstack 线程pid 进行到服务器资源商
5.退出docker容器，进入宿主机，复制日志信息进行分析。

jstack 分析

这就是当时jstack的日志，大量io进行park，等到数据库资源。简单的说，数据库挂了，等到资源的连接。

总结

1.RainBond平台
我大胆猜测，RainBond平台本质上的机制是共享内存（参考轻量云服务器）。我查看了容器的free -g 他有接近100G以上的内存。然后他的内存，应该是多台的刀片机组成的。
佐证这一个观点的就是，有的时候我开启多个实例的时候，RainBond环境需要进行资源调度，然后他们没有这么大的连续内存，导致调度不起来。
不过很气的就是，明明pod我申请了32g，我xmx设置20G，他甚至都会自杀。

2.虚拟机平台
虚拟机平台，利用dmesg -T | grep kill定位问题，调整GC参数，查看服务死机jsatck数据，就可以作为问题定位项。

3.一些服务假死的参考思路
大量阻塞线程，进行WAITING、BLOCKED 或 TIMED_WAITING（资源获取不到）_
频繁GC或者full gc的
http未设置合理的时间，资源池未释放

4.最后引用当时大佬给我的一些解决的思路（大佬太贵被优化了）
1、查看线程情况
死锁，Deadlock（重点关注）
等待资源，Waiting on condition（重点关注）
• 等待获取监视器，Waiting on monitor entry（重点关注）
阻塞，Blocked（重点关注）
• 执行中，Runnable
• 暂停，Suspended
• 对象等待中，Object.wait() 或 TIMED_WAITING
• 停止，Parked

查看线程情况：
jstack

查看死锁的线程
jstack -l

如果存在大量
死锁，Deadlock（重点关注）
等待资源，Waiting on condition（重点关注）
• 等待获取监视器，Waiting on monitor entry（重点关注）
阻塞，Blocked（重点关注）
就要分析是不是接口请求太耗时，导致链接不够用导致

2、查看堆栈情况
jmap [ option ] pid
jmap [ option ] executable core
jmap [ option ] [server-id@]remote-hostname-or-IP

-dump:[live,]format=b,file= 使用hprof二进制形式,输出jvm的heap内容到文件=. live子选项是可选的，假如指定live选项,那么只输出活的对象到文件.
-finalizerinfo 打印正等候回收的对象的信息.
-heap 打印heap的概要信息，GC使用的算法，heap的配置及wise heap的使用情况.
-histo[:live] 打印每个class的实例数目,内存占用,类全名信息. VM的内部类名字开头会加上前缀”*”. 如果live子参数加上后,只统计活的对象数量.
-permstat 打印classload和jvm heap长久层的信息. 包含每个classloader的名字,活泼性,地址,父classloader和加载的class数量. 另外,内部String的数量和占用内存数也会打印出来.

查看堆栈使用情况
jmap -heap pid

查看类占用情况
jmap -histo pid

3、查看垃圾回收情况
jstat -gc pid 2000

查看垃圾回收时间是否正常