| 作者 | 时间 |
|---|---|
| 雨中星辰、舟丶 | 2023-01-04 |
问题现象
现场运维反应程序前台页面无反应
问题排查
- F12查看接口情况
image.png
从F12可以看出，前端请求都失败了，可能是后端程序宕机导致。
-
检查进程是否还存在
# jps -l 21105 platformManage-server.jar经检查进程是存在的,没有挂掉
-
根据进程ID,查看程序资源使用情况
# top top - 09:16:50 up 138 days, 21:29, 13 users, load average: 4.09, 4.09, 4.08 Tasks: 241 total, 1 running, 179 sleeping, 0 stopped, 61 zombie Cpu(s): 20.5%us, 1.8%sy, 0.0%ni, 77.4%id, 0.1%wa, 0.1%hi, 0.1%si, 0.0%st Mem: 8115456k total, 4964640k used, 3150816k free, 129608k buffers Swap: 7812088k total, 105344k used, 7706744k free, 359824k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 21105 root 20 0 8583m 2.5g 8564 S 387 32.0 24749:52 java 2835 audadmin 16 -4 88680 792 524 S 2 0.0 37:11.48 auditd 28526 root 20 0 10508 1164 768 R 2 0.0 0:00.01 top 1 root 20 0 7852 588 520 S 0 0.0 1:41.48 init 2 root 20 0 0 0 0 S 0 0.0 0:00.00 kthreadd 3 root RT 0 0 0 0 S 0 0.0 4:41.24 migration/0 4 root 20 0 0 0 0 S 0 0.0 15:33.46 ksoftirqd/0 5 root RT 0 0 0 0 S 0 0.0 5:08.33 migration/1 6 root 20 0 0 0 0 S 0 0.0 12:42.21 ksoftirqd/1 7 root RT 0 0 0 0 S 0 0.0 7:09.71 migration/2 8 root 20 0 0 0 0 S 0 0.0 12:33.95 ksoftirqd/2 9 root RT 0 0 0 0 S 0 0.0 7:19.44 migration/3 10 root 20 0 0 0 0 S 0 0.0 11:33.97 ksoftirqd/3 11 root 20 0 0 0 0 S 0 0.0 2:29.64 events/0 12 root 20 0 0 0 0 S 0 0.0 1:58.16 events/1 13 root 20 0 0 0 0 S 0 0.0 1:54.41 events/2 14 root 20 0 0 0 0 S 0 0.0 5:14.43 events/3 15 root 20 0 0 0 0 S 0 0.0 0:00.00 cpuset 16 root 20 0 0 0 0 S 0 0.0 0:00.00 khelper 84 root 20 0 0 0 0 S 0 0.0 0:00.00 netns 87 root 20 0 0 0 0 S 0 0.0 0:00.00 async/mgr 88 root 20 0 0 0 0 S 0 0.0 0:00.00 pm 190 root 20 0 0 0 0 S 0 0.0 0:13.41 sync_supers 192 root 20 0 0 0 0 S 0 0.0 0:24.76 bdi-default 193 root 20 0 0 0 0 S 0 0.0 0:00.00 kintegrityd/0 194 root 20 0 0 0 0 S 0 0.0 0:00.00 kintegrityd/1 195 root 20 0 0 0 0 S 0 0.0 0:00.00 kintegrityd/2 196 root 20 0 0 0 0 S 0 0.0 0:00.00 kintegrityd/3 197 root 20 0 0 0 0 S 0 0.0 0:17.63 kblockd/0 198 root 20 0 0 0 0 S 0 0.0 0:01.06 kblockd/1 199 root 20 0 0 0 0 S 0 0.0 0:00.44 kblockd/2 200 root 20 0 0 0 0 S 0 0.0 0:00.38 kblockd/3 202 root 20 0 0 0 0 S 0 0.0 0:00.00 kacpid 203 root 20 0 0 0 0 S 0 0.0 0:00.00 kacpi_notify经排查，该程序占用的CPU过高已经387%，内存占用也比较高32%
-
查看服务器内存情况
# free -g total used free shared buffers cached Mem: 7 4 3 0 0 0 -/+ buffers/cache: 4 3 Swap: 7 0 7服务器总内存为7G,该程序已经占用了7*32%=2.24GB
-
查看程序的gc情况
# jstat -gcutil 21105 1000 30 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84615 365876.581 365949.920 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84615 365876.581 365949.920 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84616 365881.349 365954.688 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84616 365881.349 365954.688 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84616 365881.349 365954.688 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84616 365881.349 365954.688 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84616 365881.349 365954.688 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84617 365885.718 365959.058 开始新的gc,上次gc耗时4.369，间隔时间5s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84617 365885.718 365959.058 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84617 365885.718 365959.058 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84617 365885.718 365959.058 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84618 365889.783 365963.122 开始新的gc,上次gc耗时4.065，间隔时间4s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84618 365889.783 365963.122 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84618 365889.783 365963.122 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84618 365889.783 365963.122 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84619 365893.872 365967.211 开始新的gc,上次gc耗时4.089，间隔时间4s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84619 365893.872 365967.211 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84619 365893.872 365967.211 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84619 365893.872 365967.211 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84620 365897.955 365971.294 开始新的gc,上次gc耗时4.083，间隔时间4s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84620 365897.955 365971.294 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84620 365897.955 365971.294 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84620 365897.955 365971.294 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84621 365902.094 365975.433 开始新的gc,上次gc耗时4.139，间隔时间4s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84621 365902.094 365975.433 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84621 365902.094 365975.433 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84621 365902.094 365975.433 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84622 365906.506 365979.845 开始新的gc,上次gc耗时4.412，间隔时间4s 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84622 365906.506 365979.845 0.00 0.00 100.00 100.00 95.25 91.63 1761 73.340 84622 365906.506 365979.845可以看出随着时间变化，young GC数量没有变化，而Full GC次数频繁增加。大概4秒就增加一次Full GC，而每次Full GC平均时间为4秒，而jdk8默认的垃圾收集器是Parallel Scavenge收集器和Parallel Old收集器，他们在垃圾收集是会stop the word，导致应用程序暂停，这就意味着，该程序几乎所有的时间都用来进行垃圾收集了，应用程序就无法正常工作了。
参考JDK8内存模型Full GC通常是由于老年代满了。大量Full GC而young GC却很少，这很有可能是大对象导致的。
-
查看程序的线程情况
# top -Hp 21105 top - 09:17:27 up 138 days, 21:29, 13 users, load average: 4.10, 4.10, 4.08 Tasks: 339 total, 4 running, 335 sleeping, 0 stopped, 0 zombie Cpu(s): 20.5%us, 1.8%sy, 0.0%ni, 77.4%id, 0.1%wa, 0.1%hi, 0.1%si, 0.0%st Mem: 8115456k total, 4961076k used, 3154380k free, 125400k buffers Swap: 7812088k total, 105344k used, 7706744k free, 359896k cached PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 21111 root 20 0 8583m 2.5g 8564 R 101 32.0 5849:12 java 21108 root 20 0 8583m 2.5g 8564 R 99 32.0 5849:17 java 21109 root 20 0 8583m 2.5g 8564 R 99 32.0 5849:06 java 21110 root 20 0 8583m 2.5g 8564 R 99 32.0 5849:13 java 21105 root 20 0 8583m 2.5g 8564 S 0 32.0 0:00.00 java 21107 root 20 0 8583m 2.5g 8564 S 0 32.0 0:21.41 java 21112 root 20 0 8583m 2.5g 8564 S 0 32.0 221:40.86 java 21113 root 20 0 8583m 2.5g 8564 S 0 32.0 0:03.27 java 21114 root 20 0 8583m 2.5g 8564 S 0 32.0 0:08.56 java 21115 root 20 0 8583m 2.5g 8564 S 0 32.0 0:00.00 java 21116 root 20 0 8583m 2.5g 8564 S 0 32.0 1:41.74 java 21117 root 20 0 8583m 2.5g 8564 S 0 32.0 1:38.29 java 21118 root 20 0 8583m 2.5g 8564 S 0 32.0 0:30.92 java 21119 root 20 0 8583m 2.5g 8564 S 0 32.0 0:32.83 java 21120 root 20 0 8583m 2.5g 8564 S 0 32.0 2:34.50 java 21158 root 20 0 8583m 2.5g 8564 S 0 32.0 823:09.72 java 21159 root 20 0 8583m 2.5g 8564 S 0 32.0 0:33.89 java 21160 root 20 0 8583m 2.5g 8564 S 0 32.0 0:19.52 java 21171 root 20 0 8583m 2.5g 8564 S 0 32.0 0:07.62 java 21172 root 20 0 8583m 2.5g 8564 S 0 32.0 0:02.14 java 21173 root 20 0 8583m 2.5g 8564 S 0 32.0 13:18.52 java 21180 root 20 0 8583m 2.5g 8564 S 0 32.0 6:02.29 java 21181 root 20 0 8583m 2.5g 8564 S 0 32.0 14:24.05 java 21182 root 20 0 8583m 2.5g 8564 S 0 32.0 4:52.64 java 21183 root 20 0 8583m 2.5g 8564 S 0 32.0 8:12.81 java 21184 root 20 0 8583m 2.5g 8564 S 0 32.0 2:08.63 java 21185 root 20 0 8583m 2.5g 8564 S 0 32.0 4:44.38 java 21186 root 20 0 8583m 2.5g 8564 S 0 32.0 2:08.63 java 21189 root 20 0 8583m 2.5g 8564 S 0 32.0 0:03.28 java 21190 root 20 0 8583m 2.5g 8564 S 0 32.0 0:02.29 java 21191 root 20 0 8583m 2.5g 8564 S 0 32.0 0:01.64 java 21202 root 20 0 8583m 2.5g 8564 S 0 32.0 0:00.00 java 21210 root 20 0 8583m 2.5g 8564 S 0 32.0 0:05.51 java 21211 root 20 0 8583m 2.5g 8564 S 0 32.0 6:23.46 java从上面的top命令可以看出，pid为21111、21108、21109、21110的进程占用的CPU资源过高，优先查看这几个线程的堆栈信息
-
查看程序占用CPU高的线程堆栈信息
使用jstack查看进程堆栈信息，需要把进程id转为16进制。
十进制的pid转为十六进制（使用windows计算器的科学计数器模式、或web在线进制转换），转化后分别为：5277、5274、5275、5276# jstack 21105 |grep -A 20 5277 "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000001b44000 nid=0x5277 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007eff9801c800 nid=0x5280 waiting on condition JNI global references: 2967 sgdcloud-tj-sd-nginx02:/home/tianjin/dcloud # jstack 21105 |grep -A 20 5274 "GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000001b3f000 nid=0x5274 runnable "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000001b40800 nid=0x5275 runnable "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000001b42800 nid=0x5276 runnable "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000001b44000 nid=0x5277 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007eff9801c800 nid=0x5280 waiting on condition JNI global references: 2967 sgdcloud-tj-sd-nginx02:/home/tianjin/dcloud # jstack 21105 |grep -A 20 5275 "GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000001b40800 nid=0x5275 runnable "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000001b42800 nid=0x5276 runnable "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000001b44000 nid=0x5277 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007eff9801c800 nid=0x5280 waiting on condition JNI global references: 2967 sgdcloud-tj-sd-nginx02:/home/tianjin/dcloud # jstack 21105 |grep -A 20 5276 "GC task thread#2 (ParallelGC)" os_prio=0 tid=0x0000000001b42800 nid=0x5276 runnable "GC task thread#3 (ParallelGC)" os_prio=0 tid=0x0000000001b44000 nid=0x5277 runnable "VM Periodic Task Thread" os_prio=0 tid=0x00007eff9801c800 nid=0x5280 waiting on condition JNI global references: 2967经检查cpu占用高的线程都是GC线程。
-
查看程序的对象实例情况
# jmap -histo 21105 | head -n20 num #instances #bytes class name ---------------------------------------------- 1: 16696134 534276288 java.util.HashMap$Node 2: 6635843 278788336 [C 3: 2550506 203884360 [Ljava.util.HashMap$Node; 4: 12757 181719264 [B 5: 6631618 159158832 java.lang.String 6: 2544292 122126016 java.util.HashMap 7: 2602630 62463120 java.lang.Long 8: 2534645 60831480 java.util.concurrent.LinkedBlockingQueue$Node 9: 2484697 59632728 java.lang.Double 10: 2520356 40325696 java.util.HashMap$EntrySet 11: 2520338 40325408 java.util.HashMap$Values 12: 51396 5756352 com.sgcc.epri.dcloud.cloudmonitor.model.ProcStat 13: 31482 5416624 [Ljava.lang.Object; 14: 141596 4531072 java.util.concurrent.ConcurrentHashMap$Node 15: 32361 2847768 java.lang.reflect.Method 16: 51363 2465424 com.sgcc.epri.dcloud.cloudmoitor.server.netty.NettyFuture 17: 20033 2214376 java.lang.Class从对象实例看，程序内存中包含大量
java.util.HashMap$Node,可能是因为在程序中使用了HashMap做本地缓存，但是，由于HashMap是没有数据淘汰机制的，如果HashMap中数据没有及时清理，就会导致HashMap中对象越来越多。 导出dump文件，进行进一步分析：
jmap -dump:format=b,file=heap.bin 21105使用gceasy,进行在线分析
由于程序导出的dump文件过大，gceasy不能进行分析，卒。使用jprofile打开dump文件,分析对象实例情况
image.png
这个与jmap看的一样
- 进入Inspections页面，查看重复的字符串
image.png
从图片中看出，确实有大量重复的字符串
- 查看字符串血缘关系
image.png
从图中可以看出，这些字符串大多都在ProcStat对象中
- 查看ProcStat对象的血缘关系
image.png
字符串是ProcStat对象的startScript成员变量的值
ProcStat对象又是NettyMessage2Client成员变量data的值
NettyMessage2Client又是NettyFuture成员变量request的值
NettyFuture对象被放入了HashMapz中
结合实例图
结合实例图，可以看出NettyFuture对象的实例，只有5万+个，占用内存也只有2000+KB,该问题并不是导致程序异常的主要问题。
其他字符串，通过同样的方法分析其血缘关系
继续分析实例数量最多的java.util.HashMap$Node的情况
image.png
image.png
java.util.HashMapNode中
java.util.concurrentLinkingQueue$Node被存放在java.util.concurrentLinkingQueue中
java.util.concurrentLinkingQueue被存放在CacheMap中
-
代码分析-NettyFuture部分
image.png使用NettyFuture存放netty请求的的结果，在NettyFuture使用完毕后没有从Map中移除，导致随着程序运行时间越久，缓存的对象越多。
处理办法：客户端接受到请求响应后，将NettyFuture从map中移除即可。 -
代码分析-CacheMap部分
@Component public class CacheMap { /** * 监视数据队列 */ public LinkedBlockingQueue<Map<String,Object>> monitorQueue = new LinkedBlockingQueue<>(); ... }在该类中使用Queue作为队列，队列中存放要存储到elasticsearch中的数据
public class ConsumerMonitorRunnable implements Runnable { private static final Logger log = LoggerFactory.getLogger(ConsumerMonitorRunnable.class); @Autowired private CacheMap cacheMap; @Autowired private ElasticsearchService elasticsearchService; @Autowired private ThreadPoolExecutor eventExecutor; @PostConstruct private void setup() { eventExecutor.submit(this); } /** * 过滤监控告警数据存储到es * @description */ @Override public void run() { // 该任务持续运行 while (true){ int i = 0; List<Map<String, Object>> esParams = new ArrayList<>(); Map<String, Object> monit = null; while ((monit = cacheMap.monitorQueue.poll()) != null) { Map<String, Object> esParam=toMap(monit); //1000条提交一次 if((++i)>1000){ break; } } elasticsearchService.addData(elasticsearchService.getCloudalarmIndexFullName(), esParams); } }正常来说，该任务会不断从CacheMap到队列中获取数据，并将数据批量写入elasticsearch中，那CacheMap队列中数据过大有以下几种可能：
- 任务异常了，导致数据没有被消费
- 消费数据的速度比不上插入数据的速度，产生消息堆积
-
检查任务线程的情况
"cloudmonitor-pool-3-thread-2" #43 prio=5 os_prio=0 tid=0x00007eff9a492000 nid=0x52db waiting for monitor entry [0x000000004308c000] java.lang.Thread.State: BLOCKED (on object monitor) at org.elasticsearch.action.bulk.BulkProcessor.internalAdd(BulkProcessor.java:283) - waiting to lock <0x0000000089b76048> (a org.elasticsearch.action.bulk.BulkProcessor) at org.elasticsearch.action.bulk.BulkProcessor.add(BulkProcessor.java:268) at org.elasticsearch.action.bulk.BulkProcessor.add(BulkProcessor.java:264) at org.elasticsearch.action.bulk.BulkProcessor.add(BulkProcessor.java:250) at com.sgcc.epri.dcloud.cloudmoitor.server.common.ElasticsearchService.addData(ElasticsearchService.java:252) at com.sgcc.epri.dcloud.cloudmoitor.server.executor.ConsumerMonitorRunnable.run(ConsumerMonitorRunnable.java:114) at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748)从堆栈信息中，可以看出该线程被阻塞了，阻塞原因是elasticsearch在执行批量插入数据，长时间没有响应。
检查elasticsearch，发现确实存在问题，将elasticsearch处理正常后，程序重启也能正常运行了。
突然发现直接点Biggest Object,就能查出对象的出处了，更简单。。。
image.png
问题总结
该案例中问题主要是因为现场缺少中间件的监控告警，出问题了也不知道，导致应用的消息队列消息堆积，把内存撑爆了。
从应用程序看，主要存在两个问题：
- 使用HashMap作为数据存储的临时容器，但是，数据使用完毕后，没有及时删除。处理办法：当数据使用完毕后，及时删除HashMap中的数据
- 使用LinkedBlockingQueue作为任务队列，对队列中的数据量没有限制，队列中数据没有被及时处理，就会导致队列越来越大。处理办法：
-
在现有基础上增加个清理过期任务的线程，清理队列头部超出上限个数的元素。大致如下：
Thread clearThread = new Thread(() -> { while (true) { try { int MAX_SIZE = 1000; // 获取队列的元素隔宿 int queueSize = queue.size(); // 如果元素个数达到上限 if (queueSize > MAX_SIZE) { List<EventObject> list = new ArrayList<>(queueSize - MAX_SIZE); // 从队列头部中取出超出上限个数的元素 com.google.common.collect.Queues.drain(queue, list, queueSize - MAX_SIZE, 1, TimeUnit.SECONDS); } // 睡一会避免频繁触发 Thread.sleep(100); } catch (InterruptedException e) { e.printStackTrace(); } } }, "clear-thread");优点：对队列中数据量进行限制，避免内存无限增长，对程序改动较小。
缺点：未及时消费的消息，会被丢弃。 使用disruptor作为消息队列。
优点：可以设置可以设置队列上限，当达到上限后，消息发布者将等待队列有空闲了，才能将消息发布到队列，避免队列无限增长。
缺点：队列到达上限后，消息发布者要一直等待，直到队列中空闲，且对程序改动较大。使用单独部署的消息队列
优点：避免消息丢失。
缺点：引入额外的组件，增加了应用的复杂度，对程序改动较大。
-
参考：
