千寻

道路很长, 开始了就别停下!

0%

Java服务器load飚高排查思路

发表于 分类于 阅读次数： Valine：

Load

Load 是指对计算机干活多少的度量（WikiPedia：the system load is a measure of the amount of work that a computer system is doing），简单的说是进程队列的长度。

Load Average 就是一段时间 (1 分钟、5分钟、15分钟) 内平均 Load

通过uptime命令可以查看当前的load，如果值很高。一般情况是java某些线程长期占用资源、死锁、死循环等导致某个进程占用的CPU资源过高。大致可以从以下几个角度来排查：

排查步骤

1. 首先通过jps命令，查看当前进程id，如id为 28118

2. 查看该进程下的线程资源使用情况

1
2
3
4
5
6
7
8
9
10
11
12
13
top -Hp 28118 

32694 root      20   0 3249m 2.0g  11m S    2  6.4   3:31.12 java                      
28175 root      20   0 3249m 2.0g  11m S    0  6.4   0:00.06 java                   
28176 root      20   0 3249m 2.0g  11m S    0  6.4   1:40.79 java                   
28177 root      20   0 3249m 2.0g  11m S    0  6.4   1:41.12 java                   
28178 root      20   0 3249m 2.0g  11m S    0  6.4   1:41.11 java                   
28179 root      20   0 3249m 2.0g  11m S    0  6.4   1:41.33 java                   
28180 root      20   0 3249m 2.0g  11m S    0  6.4   1:41.58 java                   
28181 root      20   0 3249m 2.0g  11m S    0  6.4   1:40.36 java                   
28182 root      20   0 3249m 2.0g  11m S    0  6.4   1:41.02 java                   
28183 root      20   0 3249m 2.0g  11m S    0  6.4   1:40.96 java                   
28184 root      20   0 3249m 2.0g  11m S    0  6.4   4:38.30 java

3. 打印JAVA进程28118的堆栈信息

1
jstack 28118 >> stack.log

4. 将cpu消耗高的线程的pid换算为16进制

1
printf 0x%x 32694

转换后的16进制为 0x7fb6

5. 从刚才的栈日志中查找该线程正在运行的方法

1
2
3
4
5
6
7
8
grep 0x7fb6  stack.log -a10

"MSXMLProcessorThread" prio=10 tid=0x00002b469923a800 [color=darkred]nid=0x7fb6[/color] sleeping[0x00002b46b0200000]    
   java.lang.Thread.State: TIMED_WAITING (sleeping)    
        at java.lang.Thread.sleep(Native Method)    
        at com.adventnet.management.xml.MSXmlProcessor.listen(MSXmlProcessor.java:279)    
        at com.adventnet.management.xml.MSXmlProcessor.run(MSXmlProcessor.java:264)    
        at java.lang.Thread.run(Thread.java:619)

6.另外也可以查找正在运行的线程，及线程处于运行状态的位置，从这些线程中来查找资源消耗过高的代码。

1
grep RUNNABLE stack.log  -a3
1
less a.log |awk '{FS="java.lang.Thread.State:";print $2}'|sort |uniq -c |sort -nr

7、查看当前jvm内存各堆区的占比

jmap -heap 8002

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 786432000 (750.0MB)
   MaxNewSize               = 786432000 (750.0MB)
   OldSize                  = 1361051648 (1298.0MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 39845888 (38.0MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 398458880 (380.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 707788800 (675.0MB)
   used     = 383204272 (365.4520721435547MB)
   free     = 324584528 (309.5479278564453MB)
   54.14104772497107% used
Eden Space:
   capacity = 629145600 (600.0MB)
   used     = 334989624 (319.4710006713867MB)
   free     = 294155976 (280.5289993286133MB)
   53.24516677856445% used
From Space:
   capacity = 78643200 (75.0MB)
   used     = 48214648 (45.98107147216797MB)
   free     = 30428552 (29.01892852783203MB)
   61.30809529622396% used
To Space:
   capacity = 78643200 (75.0MB)
   used     = 0 (0.0MB)
   free     = 78643200 (75.0MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 1361051648 (1298.0MB)
   used     = 985748664 (940.0831832885742MB)
   free     = 375302984 (357.9168167114258MB)
   72.4255148912615% used

49647 interned Strings occupying 5512480 bytes.

其他

排查线上问题常用命令脚本

1. 查看进程pid

1
ps -ef |grep 'bbs-service' | grep -v grep |grep -v 'python' | awk '{print $2}'

2. 查看线程信息

1
2
3
4
5
6
7
8
9
10
11
jstack 27676| grep Druid-ConnectionPool- | wc -l

jstack 27676| grep Xmemcached-Reactor- 

jstack 27676| grep java.lang.Thread.State 

jstack 27676| grep DubboServerHandler-

jstack 27676| grep DubboClientHandler-

top -H -b -n 1  -p 27676 | sed '1,/^$/d' | sed '1d;/^$/d' | grep -v 27676 | sort -nrk9 | head -3

注：27676 为进程pid

3. 系统

已建立的连接数：

netstat -ant |grep ESTABLISHED |wc -l

处于等待状态的连接数：

netstat -ant |grep TIME_WAIT |wc -l

各个cpu的资源使用情况：

mpstat -P ALL

服务器异常案例

1.某应用load>7,ssh感到输入命令后,要等待1、2秒 才开始执行

  • top命令查看cpu占用率,约70%,不至于导致ssh中命令响应变慢
  • tsar查看最近的网络流量，正常
  • iostat 1，发现(虚拟机)磁盘tps达到500+非常高
  • jstack观察java中一个线程频繁操作磁盘
  • lsof命令观察打开文件，并排查代码发现配置项有误导致磁盘上出现很多小的零碎文件，引发频繁的随机访问，修改配置项后问题解决
    

2.应用Load>10，GC正常，活跃线程数很多，CPU 100%

  • ps -efL， 显示所有活跃线程ID和对应时间
  • 根据对应线程SPID找出jstack中的执行栈
  • 定位到问题代码，发现一个没同步保护的HashMap频繁并发put/get导致死循环
1
2
注意：
通常cpu使用率达到了100%，一般是某些线程在某种条件下进入死循环，退不出来

3.容灾演习之后服务无法启动

  • df –h 命令 /home 100%占用，日志文件巨大
  • 删掉由于断网引起的大量重连日志，重启

4.某应用机器load狂飙100+，报警不断

  • 收集各个系统指标，发现除了load之外没有异常，load>进程数，应用响应正常
  • jstack中Runnable状态线程很多“at
    java.io.UnixFileSystem.getBooleanAttributes0(Native Method)”
  • ps –Tel 打印所有线程状态，发现大量怨妇进程（状态D，既无法中断又无法继续）
  • 根据僵尸进程ID再次查找jstack中对应代码，为blocked的文件访问栈
  • df命令hang住
  • 联系PE同学得知NAS故障,修复后重启OK

5.Java进程健在，应用运行一段时间失去响应

  • jstat各个区域内存正常，应用服务器系统资源正常
  • 查看应用默认日志文件发现一行“WARN [common] 服务器 已停止运行:12201”
  • jstack发现有线程“JBoss Shutdown Hook”健在，查找代码发现居然有二方包代码在抛出异常后调用system.exit(0)



学习交流