记一次k8s pod频繁重启的优化之旅

1.背景

最近有运维反馈某个微服务频繁重启,客户映像特别不好,需要我们尽快看一下。

听他说完我立马到监控平台去看这个服务的运行情况,确实重启了很多次。对于技术人员来说,这既是压力也是动力,大多数时候我们都是沉浸在单调的业务开发中,对自我的提升有限,久而久之可能会陷入一种舒适区,遇到这种救火案例一时间会有点无所适从,但是没关系,毕竟......

“我只是收了火,但没有熄炉”,借用电影中的一句话表达一下此时的心情。

2.初看日志

我当即就看这个服务的运行日志,里面有大量的oom异常,如下:

org.springframework.web.util.NestedServletException: Handler dispatch failed;

nested exception ``is java.lang.OutOfMemoryError: GC overhead limit exceeded

整个服务基本可以说处于不可用状态,任何请求过来几乎都会报oom,但是这跟重启有什么关系呢?是谁触发了重启呢?这里我暂时卖个关子,后面进行解答。

3.k8s健康检查介绍

我们的服务部署在k8s中,k8s可以对容器执行定期的诊断,要执行诊断,kubelet 调用由容器实现的 Handler (处理程序)。有三种类型的处理程序:

  • ExecAction:在容器内执行指定命令。如果命令退出时返回码为 0 则认为诊断成功。

  • TCPSocketAction:对容器的 IP 地址上的指定端口执行 TCP 检查。如果端口打开,则诊断被认为是成功的。

  • HTTPGetAction:对容器的 IP 地址上指定端口和路径执行 HTTP Get 请求。如果响应的状态码大于等于 200 且小于 400,则诊断被认为是成功的。

每次探测都将获得以下三种结果之一:

  • Success(成功):容器通过了诊断。

  • Failure(失败):容器未通过诊断。

  • Unknown(未知):诊断失败,因此不会采取任何行动。

针对运行中的容器,kubelet 可以选择是否执行以下三种探针,以及如何针对探测结果作出反应:

  • livenessProbe:指示容器是否正在运行。如果存活态探测失败,则 kubelet 会杀死容器, 并且容器将根据其重启策略决定未来。如果容器不提供存活探针, 则默认状态为 Success。**

  • readinessProbe:指示容器是否准备好为请求提供服务。如果就绪态探测失败, 端点控制器将从与 Pod 匹配的所有服务的端点列表中删除该 Pod 的 IP 地址。初始延迟之前的就绪态的状态值默认为 Failure。如果容器不提供就绪态探针,则默认状态为 Success。

  • startupProbe: 指示容器中的应用是否已经启动。如果提供了启动探针,则所有其他探针都会被 禁用,直到此探针成功为止。如果启动探测失败,kubelet 将杀死容器,而容器依其 重启策略进行重启。如果容器没有提供启动探测,则默认状态为 Success。

看完探针的相关介绍,可以基本回答上面的疑点“oom和重启有什么关系?”,是livenessProbe的锅,简单描述一下为什么:

  1. 服务启动;

  2. k8s通过livenessProbe中配置的健康检查Handler做定期诊断(我们配置的是HttpGetAction);

  3. 由于oom所以HttpGetAction返回的http status code是500,被k8s认定为Failure(失败)-容器未通过诊断;

  4. k8s认为pod不健康,决定“杀死”它然后重新启动。

这是服务的Deployment.yml中关于livenessProbe和restartPolicy的配置

livenessProbe:

failureThreshold: 5

httpGet:

path: /health

port: 8080

scheme: HTTP

initialDelaySeconds: 180

periodSeconds: 20

successThreshold: 1

timeoutSeconds: 10

restartPolicy: Always

4.第一次优化

内存溢出无外乎内存不够用了,而这种不够用又粗略分两种情况:

  1. 存在内存泄漏情况,本来应该清理的对象但是并没有被清理,比如HashMap以自定义对象作为Key时对hashCode和equals方法处理不当时可能会发生;

  2. 内存确实不够用了,比如访问量突然上来了;

由于我们这个是一个老服务,而且在多个客户私有化环境都部署过,都没出过这个问题,所以我直接排除了内存泄漏的情况,那就将目光投向第二种“内存确实不够用”,通过对比访问日志和询问业务人员后得知最近客户在大力推广系统,所以访问量确实是上来了。

“不要一开始就陷入技术人员的固化思维,认为是程序存在问题”

知道了原因那解决手段也就很粗暴了,加内存呗,分分钟改完重新发布。

终于发布完成,我打开监控平台查看服务的运行情况,这次日志里确实没有oom的字样,本次优化以迅雷不及掩耳之势这么快就完了?果然是我想多了,一阵过后我眼睁睁看着pod再次重启,但诡异的是程序日志里没有oom,这一次是什么造成了它重启呢?

我使用kubectl describe pod命令查看一下pod的详细信息,重点关注Last State,里面包括上一次的退出原因和退回code。

可以看到上一次退出是由于OOMKilled,字面意思就是pod由于内存溢出被kill,这里的OOMKilled和之前提到的程序日志中输出的oom异常可千万不要混为一谈,如果pod 中的limit 资源设置较小,会运行内存不足导致 OOMKilled,这个是k8s层面的oom,这里借助官网的文档顺便介绍一下pod和容器中的内存限制。

以下pod内存限制内容来源于https://kubernetes.io/zh/docs/tasks/configure-pod-container/assign-memory-resource/

*要为容器指定内存请求,请在容器资源清单中包含 *resources:requests 字段。同理,要指定内存限制,请包含 resources:limits

以下deployment.yml将创建一个拥有一个容器的 Pod。容器将会请求 100 MiB 内存,并且内存会被限制在 200 MiB 以内:

apiVersion: v1

kind: Pod

metadata:

name: memory-demo

namespace``: mem-example

spec:

containers:

- name: memory-demo-ctr

image: polinux/stress

resources:

limits:

memory: ``"200Mi"

requests:

memory: ``"100Mi"

command: [``"stress"``]

args: [``"--vm"``, ``"1"``, ``"--vm-bytes"``, ``"150M"``, ``"--vm-hang"``, ``"1"``]

当节点拥有足够的可用内存时,容器可以使用其请求的内存。但是,容器不允许使用超过其限制的内存。如果容器分配的内存超过其限制,该容器会成为被终止的候选容器。如果容器继续消耗超出其限制的内存,则终止容器。如果终止的容器可以被重启,则 kubelet 会重新启动它,就像其他任何类型的运行时失败一样。

回归到我们的场景中来讲,虽然把jvm内存提高了,但是其运行环境(pod、容器)的内存限制并没有提高,所以自然是达不到预期状态的,解决方式也是很简单了,提高deployment.yml中memory的限制,比如jvm中-Xmx为1G,那memory的limits至少应该大于1G。

至此,第一次优化算是真正告一段落。

5.第二次优化

第一次优化只给我们带来了短暂的平静,重启次数确实有所下降,但是离我们追求的目标还是相差甚远,所以亟需来一次更彻底的优化,来捍卫技术人员的尊严,毕竟我们都是头顶别墅的人。

头顶撑不住的时候,吃点好的补补

上一次频繁重启是因为内存不足导致大量的oom异常,最终k8s健康检查机制认为pod不健康触发了重启,优化手段就是加大jvm和pod的内存,这一次的重启是因为什么呢?

前面说过k8s对http形式的健康检查地址做探测时,如果响应的状态码大于等于 200 且小于 400,则诊断被认为是成功的,否则就认为失败,这里其实忽略了一种极其普遍的情况“超时”,如果超时了也一并会归为失败。

为什么这里才引出超时呢,因为之前日志中有大量的报错,很直观的可以联想到健康检查一定失败,反观这次并没有直接证据,逼迫着发挥想象力(其实后来知道通过kubectl describe pod是可以直接观测到超时这种情况的)。

现在我们就去反推有哪些情况会造成超时:

1.cpu 100%,这个之前确实遇到过一次,是因为宿主机cpu 100%,造成大量pod停止响应,最终大面积重启;

2.网络层面出了问题,比如tcp队列被打满,导致请求得不到处理。感兴趣的可以参考我之前的文章[CLOSE_WAIT导致服务假死]

3.web容器比如tomcat、jetty的线程池饱和了,这时后来的任务会堆积在线程池的队列中;

4.jvm卡顿了,比如让开发闻风丧胆的fullgc+stw;

以上四种只是通过我的认知列举的,水平有限,更多情况欢迎大家补充。

现在我们一一排除,揪出元凶

1.看了监控宿主机负载正常,cpu正常,所以排除宿主机的问题;

2.ss -lnt查看tcp队列情况,并没有堆积、溢出情况,排除网络层面问题;

3.jstack查看线程情况,worker线程稍多但没有到最大值,排除线程池满的情况;

4.jstat gcutil查看gc情况,gc比较严重,老年代gc执行一次平均耗时1秒左右,持续时间50s到60s左右嫌疑非常大。

通过上面的排除法暂定是gc带来的stw导致jvm卡顿,最终导致健康检查超时,顺着这个思路我们先优化一把看看效果。

开始之前先补一张gc耗时的截图,为了查看的直观性,此图由arthas的dashboard产生。

说实话我对gc是没有什么调优经验的,虽然看过比较多的文章,但是连纸上谈兵都达不到,这次也是硬着头皮进行一次“调参”,调优这件事真是不敢当。

具体怎么调参呢,通过上面gc耗时的分布,很直观的拿到一个讯息,老年代的gc耗时有点长,而且次数比较频繁,虽然图里只有40次,但是相对于这个服务的启动时间来讲已经算频繁了,所以目标就是降低老年代gc频率。

从我了解的gc知识来看,老年代gc频繁是由于对象过早晋升导致,本来应该等到age达到晋升阈值才晋升到老年代的,但是由于年轻代内存不足,所以提前晋升到了老年代,晋升率过高是导致老年代gc频繁的主要原因,所以最终转化为如何降低晋升率,有两种办法:

1.增大年轻代大小,对象在年轻代得到回收,只有生命周期长的对象才进入老年代,这样老年代增速变慢,gc频率也就降下来了;

2.优化程序,降低对象的生存时间,尽量在young gc阶段回收对象。

由于我对这个服务并不是很熟悉,所以很自然的倾向于方法1“调整内存”,具体要怎么调整呢,这里借用一下美团技术博客中提到的一个公式来抛砖一下:

结合之前的那张gc耗时图可以知道这个服务活跃数据大小为750m,进而得出jvm内存各区域的配比如下:

年轻代:750m1.5 = 1125m*

老年代:750m2.5 = 1875m*

接下来通过调整过的jvm内存配比重新发布验证效果,通过一段时间的观察,老年代gc频率很明显降下来了,大部分对象在新生代被回收,整体stw时间减少,运行一个多月再没有遇到自动重启的情况,由此也验证了我之前的猜测“因为持续的gc导致健康检查超时,进而触发重启”。

至此,第二次优化告一段落。

6.第三次优化

第二次优化确实给我们带来了一段时间的安宁,后续的一个多月宕机率的统计不至于啪啪打架构部的脸。

刚安生几天,这不又来活了

有运维反馈某服务在北京客户的私有化部署环境有重启现象,频率基本上在2天一次,接收到这个讯息以后我们立马重视起来,先确定两个事:

1.个例还是普遍现象-个例,只在这个客户环境出现

2.会不会和前两次优化的问题一样,都是内存设置不合适导致的-不是,新服务,内存占用不高,gc也还好

结合前面的两个推论“个例”+“新服务,各项指标暂时正常“,我怀疑会不会是给这个客户新做的某个功能存在bug,因为目前使用频率不高,所以积攒一段时间才把服务拖垮。带着这个疑惑我采取了守株待兔的方式,shell写一个定时任务,每5s输出一下关键指标数据,定时任务如下:

#!/bin/bash

while true ; ``do

/bin/sleep 5

netstat -n | awk ``'/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}' >> netstat.log

ss -lnt >> ss.log

jstack 1 >> jstack.log

done

主要关注的指标有网络情况、tcp队列情况、线程栈情况。

就这样,一天以后这个服务终于重启了,我一一检查netstat.log,ss.log,jstack.log这几个文件,在jstack.log中问题原因剥茧抽丝般显现出来,贴一段stack信息让大家一睹为快:

"qtp1819038759-2508" #2508 prio=5 os_prio=0 tid=0x00005613a850c800 nid=0x4a39 waiting ``on condition [0x00007fe09ff25000]

java.lang.Thread.State: WAITING (parking)

at sun.misc.Unsafe.park(Native Method)

- parking to wait ``for <0x00000007221fc9e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)

at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:393)

at org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)

at org.apache.http.pool.AbstractConnPool$2.``get``(AbstractConnPool.java:253)

- locked <0x00000007199cc158> (a org.apache.http.pool.AbstractConnPool$2)

at org.apache.http.pool.AbstractConnPool$2.``get``(AbstractConnPool.java:198)

at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:306)

at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.``get``(PoolingHttpClientConnectionManager.java:282)

at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)

at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)

at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)

at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)

at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)

at com.aliyun.oss.common.comm.DefaultServiceClient.sendRequestCore(DefaultServiceClient.java:125)

at com.aliyun.oss.common.comm.ServiceClient.sendRequestImpl(ServiceClient.java:123)

at com.aliyun.oss.common.comm.ServiceClient.sendRequest(ServiceClient.java:68)

at com.aliyun.oss.``internal``.OSSOperation.send(OSSOperation.java:94)

at com.aliyun.oss.``internal``.OSSOperation.doOperation(OSSOperation.java:149)

at com.aliyun.oss.``internal``.OSSOperation.doOperation(OSSOperation.java:113)

at com.aliyun.oss.``internal``.OSSObjectOperation.getObject(OSSObjectOperation.java:273)

at com.aliyun.oss.OSSClient.getObject(OSSClient.java:551)

at com.aliyun.oss.OSSClient.getObject(OSSClient.java:539)

at xxx.OssFileUtil.downFile(OssFileUtil.java:212)

大量的线程hang在了 org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282

这个是做什么的呢?这个正是HttpClient中的连接池满了的迹象,线程在等待可用连接,最终导致jetty的线程被打满,造成服务假死,自然是不能及时响应健康检查,最终触发k8s的重启策略。

最终通过排查代码发现是由于使用阿里云oss sdk不规范导致连接没有按时归还,久而久之就造成了连接池、线程池被占满的情况,至于为什么只有北京客户有这个问题是因为只有这一家配置了oss存储,而且这个属于新支持的功能,目前尚处于试点阶段,所以短时间量不大,1到2天才出现一次重启事故。

解决办法很简单,就是及时关闭ossObject,防止连接泄漏。

7.总结

通过前前后后一个多月的持续优化,服务的可用性又提高了一个台阶,于我而言收获颇丰,对于jvm知识又回顾了一遍,也能结合以往知识进行简单的调参,对于k8s这一黑盒,也不再那么陌生,学习了基本的概念和一些简单的运维指令,最后还是要说一句“工程师对于自己写的每一行代码都要心生敬畏,否则可能就会给公司和客户带来资损”。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 204,921评论 6 478
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 87,635评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 151,393评论 0 338
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,836评论 1 277
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,833评论 5 368
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,685评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,043评论 3 399
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,694评论 0 258
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 42,671评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,670评论 2 321
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,779评论 1 332
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,424评论 4 321
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,027评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,984评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,214评论 1 260
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,108评论 2 351
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,517评论 2 343

推荐阅读更多精彩内容