故事的开始
这个故事是在一年之前,当时我们的系统运行在客户的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
查看垃圾回收时间是否正常