问题背景
调用方反馈调用我这边服务接口超时，超时时间设置是1分钟，正常最长也就几秒内返回，服务已经正常运行至少1个月，期间没有动过了。
排查过程
-
看看机器平均负载
top 命令查询负载是：load average: 21.74, 23.91, 23.76，然后通过下面命令得知有40个逻辑cpu，负载大概在60%左右了，比平时高了不少，但是不至于影响到接口响应超时，需进一步分析服务进程的CPU使用情况
grep 'model name' /proc/cpuinfo | wc -l -
找到对应服务进程中使用 cpu 最高的线程，如下，发现好多条线程CPU使用率都超过了60%，于是分析一下该线程做了啥
$ top -Hp 49363 top - 21:30:38 up 31 days, 11:13, 3 users, load average: 21.74, 23.91, 23.76 Threads: 211 total, 1 running, 210 sleeping, 0 stopped, 0 zombie %Cpu(s): 1.8 us, 0.5 sy, 0.0 ni, 97.6 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 32433152 total, 553632 free, 22283488 used, 9596032 buff/cache KiB Swap: 0 total, 0 free, 0 used. 8884564 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 49366 root 20 0 16.763g 1.556g 17472 S 66.7 5.0 82:20.37 java 49381 root 20 0 16.763g 1.556g 17472 S 66.7 5.0 82:16.58 java 49385 root 20 0 16.763g 1.556g 17472 S 66.7 5.0 82:17.64 java 49392 root 20 0 16.763g 1.556g 17472 S 66.7 5.0 82:15.83 java 49394 root 20 0 16.763g 1.556g 17472 S 66.7 5.0 82:13.98 java 49367 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:22.07 java 49368 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:17.60 java 49369 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:14.00 java 49371 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:17.33 java 49374 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:14.33 java 49375 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.55 java 49377 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.39 java 49378 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.94 java 49379 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.68 java 49382 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:16.07 java 49383 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:17.20 java 49384 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.26 java 49387 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:15.29 java 49388 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:14.57 java 49389 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:21.47 java 49391 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:16.17 java 49393 root 20 0 16.763g 1.556g 17472 S 60.0 5.0 82:11.43 java -
打印进程的线程栈信息: jstack 进程号 > 输出文件
$ jstack 49363 > stack.txt -
挑选个CPU使用率高的线程到线程栈文件 stack.txt 里面查询，如：49366，转换为16进制--> c0d6，通过 c0d6 到 stack.txt里面查找到内容如下，得知是GC线程，同时看得类似的线程提供有28个，说明可能是因为这些线程在执行FULL GC 导致是cpu飙升，同时可能业务线程被 FULL GC 阻塞了。
"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f7f4401f000 nid=0xc0d6 runnable -
分析 GC 详情
命令：jstat -gcutil 进程号 间隔时间 [次数]
$ sudo jstat -gcutil 49363 1000 S0 S1 E O M CCS YGC YGCT FGC FGCT GCT 0.00 0.00 100.00 87.04 94.37 91.63 1137 43.060 16280 6043.167 6086.227 0.00 0.00 100.00 87.04 94.37 91.63 1137 43.060 16283 6044.232 6087.292 0.00 0.00 100.00 87.04 94.37 91.63 1137 43.060 16285 6044.928 6087.988 0.00 0.00 100.00 87.04 94.37 91.63 1137 43.060 16288 6046.010 6089.070 0.00 0.00 100.00 87.04 94.37 91.63 1137 43.060 16291 6047.031 6090.091从 FGC（FULL GC 次数） 指标看出，每隔1秒，次数增大了3次左右，E（新生代）使用率100%，再看看 O(老年代)使用率也高达了87%，说明可能有大对象放到了老年代放不下，不断触发 FULL GC。先通过第6步先扩大堆内存来解决问题，然后再分析原因
为了后面进一步分析堆内存的使用情况，通过下面命令如下dump出 .hprof文件：jmap -heap 49363 -
解决问题：调大堆内存，分配老年代足够的内存
以前的配置：
-Xms1024m -Xmx1024m -Xmn512m更改后（堆增大1G：新生代不变，老年代增大1G）：
-Xms2048m -Xmx2048m -Xmn512m -
分析堆内使用情况
用 Eclipse Memory Analyser 工具打开 .hprof文件，Overview > Actions > dominator_tree ，根据 Percent 进行排序，找出头部使用，如下：
堆使用情况.png
使用最大的是 AdCacheMananger 这个类，因为里面的定时查询数据库的记录放到本地缓存的map<Integer, BigObject>里面。
其次是 Tomcat 的work线程，打开发现是报表接口的查询请求，里面包含的是返回结果，因为查询的结果比较大（大对象），老年代不够放而触发FULL GC，但是 FULL GC 后内存没有减少，因为主要大头是上面第一个的本地缓存，因此需要扩大对内存，留足够内存给老年代。
网友评论