本文主要是介绍一次关于生产环境服务无故宕机的排查过程，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！
故事的开始
这个故事是在一年之前，当时我们的系统运行在客户的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
- -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。
- max_fails=10：指定Nginx允许该服务器发生最大失败次数为10次。在超过这个次数时，Nginx会将该服务器标记为“不可用”。
- 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
查看垃圾回收时间是否正常
这篇关于一次关于生产环境服务无故宕机的排查过程的文章就介绍到这儿，希望我们推荐的文章对编程师们有所帮助！
