線上Java程式導致伺服器CPU佔用率過高的問題排除過程

標籤：pack   本地   根據   操作   導致   code   檔案   odi   img   

博文轉至：http://www.jianshu.com/p/3667157d63bb，博文更好效果看原版，轉本博文的目的就算是個書籤吧，需要時候可以定位原文學習 1、故障現象

客服同事反饋平台系統運行緩慢，網頁卡頓嚴重，多次重啟系統後問題依然存在，使用top命令查看伺服器情況，發現CPU佔用率過高。

2、CPU佔用過高問題定位2.1、定位問題進程

使用top命令查看資源佔用情況，發現pid為14063的進程佔用了大量的CPU資源，CPU佔用率高達776.1%，記憶體佔用率也達到了29.8%

[[email protected] ~]$ toptop - 14:51:10 up 233 days, 11:40,  7 users,  load average: 6.85, 5.62, 3.97Tasks: 192 total,   2 running, 190 sleeping,   0 stopped,   0 zombie%Cpu(s): 97.3 us,  0.3 sy,  0.0 ni,  2.5 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 stKiB Mem : 16268652 total,  5114392 free,  6907028 used,  4247232 buff/cacheKiB Swap:  4063228 total,  3989708 free,    73520 used.  8751512 avail Mem   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                                                                               14063 ylp       20   0 9260488 4.627g  11976 S 776.1 29.8 117:41.66 java

2.2、定位問題線程

使用ps -mp pid -o THREAD,tid,time命令查看該進程的線程情況，發現該進程的多個線程佔用率很高

[[email protected] ~]$ ps -mp 14063 -o THREAD,tid,timeUSER     %CPU PRI SCNT WCHAN  USER SYSTEM   TID     TIMEylp       361   -    - -         -      -     - 02:05:58ylp       0.0  19    - futex_    -      - 14063 00:00:00ylp       0.0  19    - poll_s    -      - 14064 00:00:00ylp      44.5  19    - -         -      - 14065 00:15:30ylp      44.5  19    - -         -      - 14066 00:15:30ylp      44.4  19    - -         -      - 14067 00:15:29ylp      44.5  19    - -         -      - 14068 00:15:30ylp      44.5  19    - -         -      - 14069 00:15:30ylp      44.5  19    - -         -      - 14070 00:15:30ylp      44.5  19    - -         -      - 14071 00:15:30ylp      44.6  19    - -         -      - 14072 00:15:32ylp       2.2  19    - futex_    -      - 14073 00:00:46ylp       0.0  19    - futex_    -      - 14074 00:00:00ylp       0.0  19    - futex_    -      - 14075 00:00:00ylp       0.0  19    - futex_    -      - 14076 00:00:00ylp       0.7  19    - futex_    -      - 14077 00:00:15

從輸出資訊可以看出，14065~14072之間的線程CPU佔用率都很高

2.3、查看問題線程堆棧

挑選TID為14065的線程，查看該線程的堆棧情況，先將線程id轉為16進位，使用printf "%x\n" tid命令進行轉換

[[email protected] ~]$ printf "%x\n" 1406536f1

再使用jstack命令列印線程堆棧資訊，命令格式：jstack pid |grep tid -A 30

[[email protected] ~]$ jstack 14063 |grep 36f1 -A 30"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007fa35001e800 nid=0x36f1 runnable "GC task thread#1 (ParallelGC)" prio=10 tid=0x00007fa350020800 nid=0x36f2 runnable "GC task thread#2 (ParallelGC)" prio=10 tid=0x00007fa350022800 nid=0x36f3 runnable "GC task thread#3 (ParallelGC)" prio=10 tid=0x00007fa350024000 nid=0x36f4 runnable "GC task thread#4 (ParallelGC)" prio=10 tid=0x00007fa350026000 nid=0x36f5 runnable "GC task thread#5 (ParallelGC)" prio=10 tid=0x00007fa350028000 nid=0x36f6 runnable "GC task thread#6 (ParallelGC)" prio=10 tid=0x00007fa350029800 nid=0x36f7 runnable "GC task thread#7 (ParallelGC)" prio=10 tid=0x00007fa35002b800 nid=0x36f8 runnable "VM Periodic Task Thread" prio=10 tid=0x00007fa3500a8800 nid=0x3700 waiting on condition JNI global references: 392

從輸出資訊可以看出，此線程是JVM的gc線程。此時可以基本確定是記憶體不足或記憶體泄露導致gc線程持續運行，導致CPU佔用過高。
所以接下來我們要找的記憶體方面的問題

3、記憶體問題定位3.1、使用jstat -gcutil命令查看進程的記憶體情況

[[email protected] ~]$ jstat -gcutil 14063 2000 10  S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT     0.00   0.00 100.00  99.99  26.31     42   21.917   218 1484.830 1506.747  0.00   0.00 100.00  99.99  26.31     42   21.917   218 1484.830 1506.747  0.00   0.00 100.00  99.99  26.31     42   21.917   219 1496.567 1518.484  0.00   0.00 100.00  99.99  26.31     42   21.917   219 1496.567 1518.484  0.00   0.00 100.00  99.99  26.31     42   21.917   219 1496.567 1518.484  0.00   0.00 100.00  99.99  26.31     42   21.917   219 1496.567 1518.484  0.00   0.00 100.00  99.99  26.31     42   21.917   219 1496.567 1518.484  0.00   0.00 100.00  99.99  26.31     42   21.917   220 1505.439 1527.355  0.00   0.00 100.00  99.99  26.31     42   21.917   220 1505.439 1527.355  0.00   0.00 100.00  99.99  26.31     42   21.917   220 1505.439 1527.355

從輸出資訊可以看出，Eden區記憶體佔用100%，Old區記憶體佔用99.99%，Full GC的次數高達220次，並且頻繁Full GC，Full GC的期間也特別長，平均每次Full GC耗時6.8秒（1505.439/220）。根據這些資訊，基本可以確定是程式碼上出現了問題，可能存在不合理建立對象的地方

3.2、分析堆棧

使用jstack命令查看進程的堆棧情況

[[email protected] ~]$ jstack 14063 >>jstack.out

把jstack.out檔案從伺服器拿到本地後，用編輯器尋找帶有項目目錄並且線程狀態是RUNABLE的相關資訊，可以看出ActivityUtil.java類的447行正在使用HashMap.put()方法

Paste_Image.png3.3、代碼定位

開啟項目工程，找到ActivityUtil類的477行，代碼如下：

Paste_Image.png

找到相關同事瞭解後，這段代碼會從資料庫中擷取配置，並根據資料庫中remain的值進行迴圈，在迴圈中會一直對HashMap進行put操作。

查詢資料庫中的配置，發現remain的數量巨大

Paste_Image.png

至此，問題定位完畢。

 

 

線上Java程式導致伺服器CPU佔用率過高的問題排除過程