今天前端一直在群里说,服务是不是又挂了?一直返回 503。我一听这不对劲,赶紧看了一眼 K8S 的 pod 状态,居然重启了4次。测试环境只有一个副本,所以赶紧把副本数给上调到了3个。
堵住前端的嘴,免得破坏我在老板心目中的形象,我害怕下次加薪名单没有我,而优化名单有我。
暂时安抚好前端之后我得立马看看哪里出问题了,先看看 K8S 为什么让这个容器领盒饭了。
Last State: Terminated
Reason: OOMKilled
看起来是 JVM 胃口太大,被 K8S 嫌弃从而被赶走了。看看最近谁提交部署了,把人拉过来拷问一番。
代码摆出来分析,发现这小子每次使用http调用都会 new 一个连接池对象。一次业务请求使用了 6 次 http 调用,也就是会 new 6 个连接池对象。有可能是这里的问题,抓紧改了发上去测试看看。
不出意外的话又出意外了,上去之后也没缓解,那就不是这个问题了。要找到具体的原因还是不能瞎猜,得有专业的工具来进行分析才行。之前为了省点镜像空间,所以使用了 jre
的基础镜像。
总所周知,jre
只有一个运行环境,是没有开发工具的。所以我们得使用 jdk
。你说我为省那点空间干什么?都想抽自己了。我们应该以 "让打靶老板花钱"为荣,以 "为打靶老板省钱"为耻。
把JDK准备好之后,就要开始我的第一次了。开始之前总是需要洗白白的,把一些影响心情的东西全部处理掉,就像这个 Skywalking,之前一直跟着我。但现在影响到我了,我得暂时把它放一边。不然他会在进行的过程中一直蹦出来烦人。
使用 Skywalking
需要设置此环境变量,每一次执行Java相关的命令都会执行 Skywalking
的一些操作,可以使用 unset
命令把环境变量临时置空。因为等我做完还是需要他来继续给我工作的。
unset JAVA_TOOL_OPTIONS
琐碎事处理完了之后,就得挑个技师才行。这行命令一把梭就会打印出所有 java
进程信息,这主要是为了获取到 vmid
,也就是技师的编号。
jps -lv
root@xxx-ext-6464577d8-vvz2n:/app# jps -lv
608 sun.tools.jps.Jps -Denv.class.path=.:/usr/local/java/lib/rt.jar:/usr/local/java/lib/dt.jar:/usr/local/java/lib/tools.jar -Dapplication.home=/usr/local/openjdk-8 -Xms8m
7 /root/app/xxx-ext.jar -javaagent:/skywalking/agent/skywalking-agent.jar -Dfile.encoding=UTF-8 -Xms1024m -Xmx2048m
568 sun.tools.jstat.Jstat -javaagent:/skywalking/agent/skywalking-agent.jar -Denv.class.path=.:/usr/local/java/lib/rt.jar:/usr/local/java/lib/dt.jar:/usr/local/java/lib/tools.jar -Dapplication.home=/usr/local/openjdk-8 -Xms8m
这里总共查到3个Java进程,608 jps
、7 xxx-ext
和 568 jstat
。中间这个 7 号技师 xxx-ext
就是我相中的,我将会把第一次交给他。
选完技师就正式开始了,过程中要时刻关心对方的身体状态。隔几秒钟就问一下状态怎么样?为了方便时刻了解对方的身体状态,可以用这个命令每隔5s就问一下。如果你对自己的能力有信心可以把间隔设置短一些。
# jstat -gcutil {vmid} {间隔毫秒}
jstat -gcutil 7 5000
root@xxx-ext-6464577d8-vvz2n:/app# jstat -gcutil 7 5000
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
99.96 0.00 100.00 100.00 95.85 94.74 178 8.047 8 3.966 12.012
99.97 0.00 100.00 100.00 95.50 94.33 178 8.047 11 8.072 16.118
99.99 0.00 100.00 100.00 95.51 94.33 178 8.047 14 12.408 20.455
100.00 0.00 100.00 100.00 95.48 94.30 178 8.047 18 17.140 25.187
100.00 0.00 100.00 100.00 95.48 94.30 178 8.047 23 22.730 30.776
100.00 0.00 100.00 100.00 95.48 94.30 178 8.047 27 27.035 35.082
100.00 0.00 100.00 100.00 95.49 94.30 178 8.047 32 32.614 40.661
虽然是第一次,但对方给回来的信息务必要了然于胸。知己知彼胜券在握,所以要把下面的心法记住。这会影响我们下一步的动作。
S0/S1 是Survivor区空间使用率
E 是新生代空间使用率
O 是老年代空间使用率
YGC 是 Young GC 次数
YGCT 是 Young GC 总耗时
FGC 是 Full GC 次数
FGCT 是 Full GC 总耗时
当对方的状态到达一个关键点的时候,一般是老年代满,或者是新生代满,这就表示对方快溢出来了。像我提供的这个示例,E 和 O 的使用率都是100,就说明对方不仅满了,还快噶了。我们得赶紧把这个关键时刻详细探究一下,看看是哪个对象让对方感觉到满的。
用这个命令查询对方体内对象占用排名,不用贪多,前10个就绰绰有余了。你能把前10个全部弄清楚就够牛了。
jmap -histo:live 7 | head -n 10
root@xxx-ext-6464577d8-vvz2n:/app# jmap -histo:live 7 | head -n 10
num #instances #bytes class name
----------------------------------------------
1: 454962 1852234368 [C
2: 1773671 56757472 java.util.HashMap$Node
3: 881987 30188352 [B
4: 55036 19781352 [Ljava.util.HashMap$Node;
5: 857235 13715760 java.lang.Integer
6: 852094 13633504 com.knuddels.jtokkit.ByteArrayWrapper
7: 454195 10900680 java.lang.String
8: 104386 6436624 [Ljava.lang.Object;
9: 191593 6130976 java.util.concurrent.ConcurrentHashMap$Node
10: 63278 5568464 java.lang.reflect.Method
可以看到对方已经在边缘了,我们要抓紧分析了。我提供的这个示例,排名前三分别是 [C
、java.util.HashMap$Node
和 [B
,[C
表示字符数组,[B
表示字节数组。看来对方偏爱 [C
,占用差不多1.7G,需要重点分析它。
这一步就到了十字路口,关键点在于我们能不能从这里分析得到对方偏爱的对象,从而定位到代码中的问题点。一旦我们定位到代码中的问题点,那就证明对方已经被我们拿捏了,流程结束。
那就开始分析吧,先看看最近哪个瘪犊子提交了代码,把他拉过来。然后看最近改动的代码哪里和 [C
相关,一般是 List<String>
、StringBuffer
这类对象。
我没想到小丑竟是我自己🤡,有一个接口入参是一个 List<ID>
,当这个 list 传了空的时候,就会把库里的所有数据都查出来。
破案了,这次把对方完全拿捏了,流程结束。
如果上一步无法拿捏,那就不要讲武德了。把对方的一举一动dump下来,最终导出成堆快照来分析。
dump 时间取决于数据量
jmap -dump:live,format=b,file=heap.hprof 7
root@xxx-ext-6464577d8-vvz2n:/app# jmap -dump:live,format=b,file=heap.hprof 7
Dumping heap to /app/heap.hprof ...
Heap dump file created
将dump文件从pod中复制出来
kubectl cp <ns>/<pod>:/app/heap.hprof ./heap.hprof
kubectl cp test/xxx-ext-6464577d8-vvz2n:/app/heap.hprof ./heap.hprof
我摊牌了,这一步我压根没做。
当我想从pod中把对快照复制出来的时候磁盘空间不够,然后pod就被 K8S 这个暴脾气干了,只剩下我颤抖的手无力地放在键盘上。
Ref
https://juejin.cn/post/7006229454523482126