前言随着 AI 的发展日常开发中想必大家都已经用上了 AI但是生产事故仍然依赖人工经验去排查。这也是 AI 很难完全替代人的一个场景毕竟不可能让 Agent 直接连接生产环境进行操作这存在较大的风险。由于生产事故的诱因千千万本文也无法覆盖所有场景主要记录一次实际生产事故的排查过程并提供一种排查思路。表现现象java项目报大量错误redis连接失败、JDBC连接异常CPU飙升由于项目本身并没有达到高并发级别只是偶尔存在并发请求数也远没有达到能够将 Redis 击穿的程度。因此排查时不能只关注最终表现出来的异常。Redis 和 JDBC 连接失败很可能只是因为CPU 长时间处于高负载状态导致 JVM 没有足够的处理能力处理正常请求。cpu占用过高大多数时候我们可能会想到arthas但是这里需要注意一点如果服务本身在高负载的时候arthas是及其可能连不上的而且很多场景arthas并没有想象中好用。输出线程dump信息和cpu占用信息top使用top命令能看到cpu占用情况找到该项目的pid或者ps -ef | grep 都可以方式多样我们假设pid是30314执行命令readlink -f /proc/30314/exe例如返回/data/jdk1.8.0_261/bin/java表示该服务被哪个jdk启动适用于服务器有多个jdk场景如果是容器启动则需要先找到容器宿主机之间的路径映射。输入以下命令表示将pid30314的项目线程dump输出至/tmp/目录下的thread-30314.log文件中/data/jdk1.8.0_261/bin/jcmd 30314 Thread.print /tmp/thread-30314.log 21使用top命令 找到cpu占用高的线程top -Hp 30314 -b -n 1 /tmp/top-30314.txt打开后能看到类似以下信息PID USER PR NI VIRT RES SHR S %CPU %MEM TIME COMMAND 30316 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:18.63 java 30318 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:10.66 java 30319 deity 20 0 8181972 5.5g 14296 R 68.8 17.7 16:14.22 java 30317 deity 20 0 8181972 5.5g 14296 R 62.5 17.7 16:15.18 java 30320 deity 20 0 8181972 5.5g 14296 S 18.8 17.7 4:26.14 java 30324 deity 20 0 8181972 5.5g 14296 S 6.2 17.7 7:04.65 java这个命令展示的PID其实是TID 线程id下文用TID代替 防止概念混淆。我们以TID30316分析将它转成16进制得到 0x766c在thread-30314.log中搜索发现结果是GC task thread#0 (ParallelGC) os_prio0 tid0x00007f708c01e800 nid0x766c runnable类似的 其它几个TID搜索后发现 也是gc线程所以很明显是由于gc负载过大 导致CPU飙升但gc也只是表现结果我们需要知道是什么代码导致了gc困难。分析到这里我们会发现 会有两种场景① 业务线程我们自己写的代码线程导致CPU飙升② GC线程导致CPU飙升如果是业务线程那么这个时候基本就能知道是什么代码导致的了不幸的是 博主遇到的场景是业务线程负载已经结束 是GC困难所以此时看top命令看arthas的memory也好 thread也罢已经看不出真正的诱因这也是前文提到有些场景arthas没想象中好用的原因。分析profiler 和 heapdump到这里已经算是难点了我们或许看过很多去找哪个线程导致cpu过高的实战案例可是如果这个业务线程结束了我们就应该转变思路去分析内存了。profiler在本案例中 作用较小 作为常用手段 这里也一并补充开始采集火焰图:profiler start过30s 或1-2分钟务必及时停止采集结合自己项目情况估算主要是需要一个时间窗口来收集内存信息 停止采集火焰图 并输出至/tmp/目录profiler stop --format html --file /tmp/gc.htmlprofiler 是告诉我们 什么代码正在生成对象导致GC过多前文提过业务线程已经执行完了是残留的内存所以我们需要将Heap Dump输出。将heap dump输出至 /tmp/目录 (arthus里面执行)heapdump /tmp/heap.hprofjdk原生(以jdk路径/data/jdk1.8.0_261 pid9815为例)/data/jdk1.8.0_261/bin/jmap -dump:formatb,file/tmp/heap.hprof 9815这个文件非常大占用的堆内存多大 它就多大从堡垒机等中间服务直接下载回本地可能失败可以切割下载注意hprof是二进制文件 不能简单切割 一定要 -b切割split -b 500M heap.hprof heap.hprof.part-执行完成后检查ls -lh heap-live.hprof*应该看到(假设大小为1.5G 切割成3份)heap-live.hprof heap-live.hprof.part-aa heap-live.hprof.part-ab heap-live.hprof.part-ac下载回本地后 再合并windows注意需要合并的文件名替换成真实的:copy /b heap-live.hprof.part-aaheap-live.hprof.part-abheap-live.hprof.part-ac heap-live.hproflinux:cat heap-live.hprof.part-* heap-live.hprof接着需要下载eclipse MAT将合并后的文件通过MAT打开如果合并错误 MAT会打开失败且MAT本身需要分配较大内存否则同样无法打开。通过MAT的Histogram ,See stacktrace通过引用链 可以进一步定位 到底是什么业务代码一直持有这些数据 (至此则是MAT工具的使用本文不过多阐述可以结合AI分析)经过排查后 发现是 导出接口导致大批量数据查询中大量对象转换、时间转换且持续引用list无法释放业务人员在点击导出 没得到响应后又重复发起了多次导出直接导致gc拉满。这也给出警示在大批量导出接口时需要加锁避免同时/重复操作本次事故流程业务代码大批量数据持有对象引用-堆内存拉满-gc负载高-cpu过高导致-jdbc/redis连接失败-服务不可用
在NLP中的实战应用与优化)
