Java 问题 定位
遇到问题第一反应,看监控,看报警,看日志,定位问题。
线上故障主要会包括 CPU、磁盘、内存以及网络问题。
看监控,先看机房有没有问题,然后看机房里的机器有问题,是CPU load高,磁盘IO高,内存不够用,还是网络不稳定。或者可以和历史监控做对比,找出异常情况。
如果找不出来,看日志吧,看看有没有异常信息。
** 如果多台机器出问题 **
- 一般情况下,线上出问题是内存问题居多,因为写代码的时候可能没想到所有情况,导致内存不够用,频繁gc,甚至OOM,通过监控、报警、日志 判断
- 网络问题,通过监控判断
- CPU问题
- 调用的其它服务出问题 (数据库 第三方接口)
- 某个机房容器全部挂掉 可能性较小
** 一台机器出问题 **
- 检查容器是否有问题,宿主机故障,容器故障,容器网络有问题
- 流量分布不均衡,导致某台机器流量比较多
把问题范围确定了以后,基本可以从 CPU、内存、IO(文件IO 网络IO) 来确认和解决问题。
CPU
用top命令查看整体情况,load值、cpu利用率 是否正常
如果load值正常,代表系统负载正常
如果load值异常,需要看是什么原因导致,需要进一步查看
如果CPU利用率正常,代表此时没有耗费CPU的操作
如果CPU利用率很高,需要分析是什么原因导致。
系统负载
代表单位时间内正在运行或等待的进程或线程数,代表了系统的繁忙程度。
CPU利用率
则代表单位时间内一个线程或进程实时占用CPU的百分比。
一个进程或者线程在运行时,未必都在实时的利用CPU的。
下面是top命令对应的样例
[wkq@VM_77_25_centos ~]$ top
top - 16:12:30 up 146 days, 22:27, 1 user, load average: 84.71, 104.35, 113.82
Tasks: 19 total, 1 running, 18 sleeping, 0 stopped, 0 zombie
Cpu0 : 6.9%us, 9.0%sy, 0.0%ni, 40.9%id, 37.8%wa, 2.6%hi, 2.3%si, 0.5%st
Cpu1 : 6.1%us, 8.6%sy, 0.0%ni, 46.5%id, 35.5%wa, 1.0%hi, 1.6%si, 0.6%st
Cpu2 : 7.0%us, 9.1%sy, 0.0%ni, 41.7%id, 38.4%wa, 2.6%hi, 0.7%si, 0.5%st
Cpu3 : 6.5%us, 8.9%sy, 0.0%ni, 48.0%id, 34.6%wa, 1.0%hi, 0.4%si, 0.6%st
Cpu4 : 7.0%us, 9.0%sy, 0.0%ni, 42.2%id, 38.2%wa, 2.6%hi, 0.6%si, 0.5%st
Cpu5 : 6.6%us, 9.0%sy, 0.0%ni, 48.7%id, 33.8%wa, 1.0%hi, 0.3%si, 0.6%st
Cpu6 : 6.8%us, 8.9%sy, 0.0%ni, 42.7%id, 38.0%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu7 : 6.5%us, 8.9%sy, 0.0%ni, 49.5%id, 33.3%wa, 1.0%hi, 0.3%si, 0.6%st
Cpu8 : 6.9%us, 9.0%sy, 0.0%ni, 42.9%id, 37.6%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu9 : 6.5%us, 8.9%sy, 0.0%ni, 49.3%id, 33.2%wa, 1.0%hi, 0.5%si, 0.6%st
Cpu10 : 6.9%us, 9.0%sy, 0.0%ni, 43.2%id, 37.3%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu11 : 6.5%us, 8.9%sy, 0.0%ni, 49.6%id, 32.9%wa, 1.0%hi, 0.4%si, 0.6%st
Cpu12 : 6.9%us, 8.9%sy, 0.0%ni, 43.4%id, 37.1%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu13 : 6.6%us, 8.9%sy, 0.0%ni, 50.1%id, 32.4%wa, 1.0%hi, 0.4%si, 0.6%st
Cpu14 : 6.9%us, 8.9%sy, 0.0%ni, 43.7%id, 36.9%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu15 : 6.7%us, 8.9%sy, 0.0%ni, 50.5%id, 31.9%wa, 1.0%hi, 0.3%si, 0.6%st
Cpu16 : 7.0%us, 8.9%sy, 0.0%ni, 43.9%id, 36.6%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu17 : 6.6%us, 8.8%sy, 0.0%ni, 50.8%id, 31.8%wa, 1.0%hi, 0.4%si, 0.6%st
Cpu18 : 7.0%us, 8.8%sy, 0.0%ni, 44.2%id, 36.4%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu19 : 6.6%us, 8.9%sy, 0.0%ni, 51.1%id, 31.5%wa, 1.0%hi, 0.2%si, 0.6%st
Cpu20 : 6.9%us, 8.8%sy, 0.0%ni, 44.4%id, 36.2%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu21 : 6.6%us, 8.9%sy, 0.0%ni, 50.9%id, 31.7%wa, 1.0%hi, 0.3%si, 0.6%st
Cpu22 : 6.9%us, 8.8%sy, 0.0%ni, 44.6%id, 36.0%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu23 : 6.6%us, 8.9%sy, 0.0%ni, 51.4%id, 31.2%wa, 1.0%hi, 0.2%si, 0.6%st
Cpu24 : 6.9%us, 8.8%sy, 0.0%ni, 44.8%id, 35.8%wa, 2.6%hi, 0.5%si, 0.5%st
Cpu25 : 6.6%us, 8.9%sy, 0.0%ni, 51.4%id, 31.2%wa, 1.0%hi, 0.2%si, 0.6%st
Cpu26 : 6.3%us, 8.2%sy, 0.0%ni, 51.5%id, 29.1%wa, 2.8%hi, 1.5%si, 0.6%st
Cpu27 : 6.1%us, 8.9%sy, 0.0%ni, 45.9%id, 37.3%wa, 1.0%hi, 0.2%si, 0.6%st
Mem: 49283096k total, 48746440k used, 536656k free, 206260k buffers
Swap: 0k total, 0k used, 0k free, 7044244k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 105m 212 0 S 0.0 0.0 0:00.08 sh
8 root 20 0 66352 1244 500 S 0.0 0.0 0:00.00 sshd
10 root 20 0 114m 1200 592 S 0.0 0.0 43:28.46 crond
[wkq@VM_77_25_centos ~]$
可以看到这是一个28核CPU,load average: 84.71, 104.35, 113.82
也就是说 最近1分钟系统平均负载是 84.71,最近5分钟系统平均负载是 104.35,最近15分钟系统平均负载是 113.82
可以看到负载比较高
系统平均负载高,一般是计算量大导致的,比如 大量计算(count++)、死循环、频繁往map里put需要计算hash、
[wkq@VM_77_25_centos ~]$ top
top - 16:02:17 up 69 days, 23:08, 1 user, load average: 0.03, 0.03, 0.05
Tasks: 68 total, 2 running, 66 sleeping, 0 stopped, 0 zombie
%Cpu(s): 0.3 us, 0.3 sy, 0.0 ni, 99.0 id, 0.3 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 1883844 total, 75024 free, 430228 used, 1378592 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 1266684 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3031 wkq 20 0 2692228 354060 4156 S 0.3 18.8 477:30.26 java
16414 root 20 0 612232 13740 2380 S 0.3 0.7 21:40.11 barad_agent
1 root 20 0 41020 2900 1816 S 0.0 0.2 4:49.45 systemd
从上面的信息可以看到 load average: 0.03, 0.03, 0.05
也就是说 最近1分钟系统平均负载是 0.03,最近5分钟系统平均负载是 0.03,最近15分钟系统平均负载是 0.05
可以看到 负载特别低
load 值
load average 代表 1分钟、5分钟、15分钟 的系统平均负载,从这三个数字,可以判断系统负荷是大还是小。
单核CPU,当CPU完全空闲的时候,平均负荷为0;当CPU工作量饱和的时候,平均负荷为1。
因此 load average 这三个数值越低,代表系统负荷越小。单核CPU load值0.7比较合理
8核CPU load值 7 - 8 比较合理
如果电脑里只有一个CPU,把CPU看成一条单行桥,桥上只有一个车道,所有的车都必须从这个桥上通过。那么
系统负荷为0,代表桥上一辆车也没有
系统负荷0.5,意味着桥上一半路段上有车
系统负荷1,意味着桥上道路已经被车占满
系统负荷1.7,代表着在桥上车子已经满了(100%),同时还有70%的车子在等待从桥上通过
查找CPU使用率高的线程
[wkq@VM_77_25_centos log]$ jps -l
147 org.springframework.boot.loader.PropertiesLauncher
361773 sun.tools.jps.Jps
[wkq@VM_77_25_centos log]$
[wkq@VM_77_25_centos log]$ top -p 147 -H
top - 20:29:01 up 798 days, 3:59, 3 users, load average: 17.93, 17.65, 16.52
Tasks: 363 total, 5 running, 358 sleeping, 0 stopped, 0 zombie
Cpu(s): 14.6%us, 4.5%sy, 0.1%ni, 72.7%id, 5.9%wa, 0.0%hi, 2.2%si, 0.0%st
Mem: 527951688k total, 388728604k used, 139223084k free, 1940564k buffers
Swap: 16777212k total, 792k used, 16776420k free, 149503456k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
399 admin 20 0 25.5g 657m 15m S 4.3 0.1 1:02.00 java
396 admin 20 0 25.5g 657m 15m R 2.7 0.1 0:37.58 java
398 admin 20 0 25.5g 657m 15m S 2.7 0.1 0:37.39 java
395 admin 20 0 25.5g 657m 15m S 2.3 0.1 0:34.83 java
397 admin 20 0 25.5g 657m 15m S 2.3 0.1 0:34.69 java
160 admin 20 0 25.5g 657m 15m S 2.0 0.1 0:46.18 java
161 admin 20 0 25.5g 657m 15m S 2.0 0.1 0:46.11 java
618 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.01 java
624 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.13 java
645 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.05 java
658 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.13 java
715 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.10 java
727 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:10.96 java
745 admin 20 0 25.5g 657m 15m S 1.3 0.1 0:11.15 java
293 admin 20 0 25.5g 657m 15m S 1.0 0.1 149:24.83 java
580 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:10.95 java
581 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:10.90 java
584 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.13 java
592 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.08 java
593 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:10.92 java
594 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.00 java
598 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.01 java
604 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.14 java
605 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:10.98 java
607 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:10.97 java
610 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.03 java
611 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.20 java
622 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.04 java
625 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.01 java
626 admin 20 0 25.5g 657m 15m S 1.0 0.1 0:11.07 java
[wkq@VM_77_25_centos log]$
用
top -p pid -H
来找到 CPU 使用率比较高的一些线程
-p
用于指定进程
-H
用于获取每个线程的信息
[wkq@VM_77_25_centos log]$ printf '%x\n' 399
18f
[wkq@VM_77_25_centos log]$
[wkq@VM_77_25_centos log]$ jstack 147 | grep 'nid=0x18f'
"XNIO-1 Accept" #114 prio=5 os_prio=0 tid=0x00007f1c06007000 nid=0x18f runnable [0x00007f1b3c97d000]
[wkq@VM_77_25_centos log]$
[wkq@VM_77_25_centos log]$
linux里nid用的是10进制,但是jstack里用的是16进制
将占用最高的 pid 转换为 16 进制 printf ‘%x\n’ ,根据pid得到nid找到CPU占用的线程id后,为了确定这些是什么线程,需要使用 jstack 命令来查看这几个是什么线程。
jstack -l 13050
> stack.log
在 jstack 中找到相应的堆栈信息 grep 'nid' stack.log
,可以看到相对比较详细的线程信息。
cat jstack.log | grep "java.lang.Thread.State" | sort -nr | uniq -c
用来查看 WAITING 和 TIMED_WAITING 状态的线程。
内存
内存这块出问题的点会多一些,JVM参数配置,代码里未释放、线程池不合理、容器里线程复用导致内存未释放
但是绝大部分情况都是开发人员不合理使用或不合理配置导致
首先通过 top 命令 或者 free 命令查看内存使用情况
然后根据系统内存、JVM参数配置内存、实际使用内存、空闲内存 来判断是什么原因
这里需要排查问题的人了解 JVM运行时内存区域的划分,否则会找不到问题
查看空闲内存是否够用 (根据实际情况判断)
查看 JVM使用内存+堆外内存 是否超过系统内存,如果超过,JVM申请不到内存,服务一般会直接挂掉
查看JVM参数配置是否合理,可以通过 jstat 来辅助判断
通过jstat分析内存时,需要根据具体的垃圾回收器来分析,不同的垃圾回收器参数不一样。
[wkq@VM_77_25_centos ~]$ jstat -gc -h5 -t 13050 1000 10
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
217492.5 8512.0 8512.0 0.0 77.3 68160.0 13154.8 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217493.7 8512.0 8512.0 0.0 77.3 68160.0 13154.8 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217494.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217495.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217496.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
Timestamp S0C S1C S0U S1U EC EU OC OU MC MU CCSC CCSU YGC YGCT FGC FGCT GCT
217497.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217498.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217499.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217500.7 8512.0 8512.0 0.0 77.3 68160.0 14055.9 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
217501.7 8512.0 8512.0 0.0 77.3 68160.0 14068.0 963392.0 60728.2 77732.0 71386.5 11984.0 9862.9 133 2.921 8 0.947 3.868
[wkq@VM_77_25_centos ~]$
[wkq@VM_77_25_centos ~]$ jstat -gcutil -h5 -t 13050 1000 10
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
217569.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217570.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217571.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217572.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217573.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
Timestamp S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
217574.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217575.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217576.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217577.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
217578.9 0.00 0.91 23.55 6.30 91.84 82.30 133 2.921 8 0.947 3.868
[wkq@VM_77_25_centos ~]$
网络IO
还是先看监控
网络层面的问题一般都比较复杂,场景多,定位难
超时
磁盘IO
其它
看日志,定位是传参的问题,还是程序逻辑,还是代码里内存未释放。
重现问题
分析问题
用 JMX JMC jvisualvm 查看Java服务在运行过程中的内存、GC、线程等信息。
VisualVM是Sun的一个OpenJDK项目,它是集成了多个JDK命令工具的一个可视化工具,它主要用来监控JVM的运行情况,可以用它来查看和浏览Heap Dump、Thread Dump、内存对象实例情况、GC执行情况、CPU消耗以及类的装载情况,也可以使用它来创建必要信息的日志。
也可以使用jstat命令来堆Java堆内存的使用情况进行统计 pid 3031
jstat -gcutil 3031 1000 10
[wkq@VM_77_25_centos ~]$ jstat -gcutil 3031 1000 10
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
0.00 100.00 27.27 78.98 97.75 97.20 155 1.642 0 0.000 1.642
YGC: 从启动到采样时Young Generation GC的次数
YGCT: 从启动到采样时Young Generation GC所用的时间 (s).
FGC: 从启动到采样时Old Generation GC的次数.
FGCT: 从启动到采样时Old Generation GC所用的时间 (s).
GCT: 从启动到采样时GC所用的总时间 (s).
查看CPU 内存使用情况
使用 top
命令,查看CPU 内存使用情况
获取占用CPU最高的线程id
jstack是java虚拟机自带的一种堆栈跟踪工具,用于打印出给定的java进程ID或core file或远程调试服务的Java堆栈信息。使用下面命令,将java进程的堆栈信息打印到文件中
jstack -l 12309 > stack.log
是哪些对象占用了内存
用VisualVM来生成headdump文件。
在机器上使用jmap命令来生成head dump文件。
jmap -dump:live,format=b,file=headInfo.hprof 12309
live这个参数表示我们需要抓取的是目前在生命周期内的内存对象,也就是说GC收不走的对象,在这种场景下,我们需要的就是这些内存的信息。生成了hprof文件后,可以拉回到本地,使用VisualVM来打开它进行分析。
使用下面的命令,来查看占用内存最多的类型:
jmap -histo 12309 > heap.log
能否对堆内对象进行查询
如果能够分析出相似度高的字符串,那么有比较大的可能是这些字符串存在泄漏,从而可以缩小问题代码的范围。确实是有这么一种工具来对堆内的对象进行分析,也就是OQL(Object Query Language),在VisualVM中可以对headdump文件执行对象查询,下面是一个示例,查找包含内容最多的List:
select map(top(heap.objects('java.util.ArrayList'), 'rhs.size - lhs.size', 5),"toHtml(it)+'='+it.size")
References
[1] 从一次线上故障思考 Java 问题定位思路
[2] 从一次线上故障思考 Java 问题定位思路
[3] automated-heap-dump-analysis-finding
[4] 记一次Full GC频繁排查过程
[5] JAVA 线上故障排查完整套路!牛掰!
[6] 25 | 内存持续上升,我该如何排查问题?