Java 问题 定位

遇到问题第一反应,看监控,看报警,看日志,定位问题。
线上故障主要会包括 CPU、磁盘、内存以及网络问题。
看监控,先看机房有没有问题,然后看机房里的机器有问题,是CPU load高,磁盘IO高,内存不够用,还是网络不稳定。或者可以和历史监控做对比,找出异常情况。
如果找不出来,看日志吧,看看有没有异常信息。

** 如果多台机器出问题 **

  1. 一般情况下,线上出问题是内存问题居多,因为写代码的时候可能没想到所有情况,导致内存不够用,频繁gc,甚至OOM,通过监控、报警、日志 判断
  2. 网络问题,通过监控判断
  3. CPU问题
  4. 调用的其它服务出问题 (数据库 第三方接口)
  5. 某个机房容器全部挂掉 可能性较小

** 一台机器出问题 **

  1. 检查容器是否有问题,宿主机故障,容器故障,容器网络有问题
  2. 流量分布不均衡,导致某台机器流量比较多

把问题范围确定了以后,基本可以从 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

其它

  1. 看日志,定位是传参的问题,还是程序逻辑,还是代码里内存未释放。

  2. 重现问题

  3. 分析问题
    用 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 | 内存持续上升,我该如何排查问题?