記一次線上Java程式導緻伺服器CPU占用率過高的問題排除過程

1、故障現象 客服同僚回報平台系統運作緩慢，網頁卡頓嚴重，多次重新開機系統後問題依然存在，使用top指令檢視伺服器情況，發現CPU占用率過高。 2、CPU占用過高問題定位 2.1、定位問題程序 使用top指令檢視資源占用情況，發現pid為14063的程序占用了大量的CPU資源，CPU占用率高達776.1%，記憶體占用率也達到了29.8% [ylp@ylp-web-01 ~]$ top top - 14:51:10 up 233 days, 11:40, 7 users, load average: 6.85, 5.62, 3.97 Tasks: 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 st KiB Mem : 16268652 total, 5114392 free, 6907028 used, 4247232 buff/cache KiB 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指令檢視該程序的線程情況，發現該程序的多個線程占用率很高 [ylp@ylp-web-01 ~]$ ps -mp 14063 -o THREAD,tid,time USER %CPU PRI SCNT WCHAN USER SYSTEM TID TIME ylp 361 - - - - - - 02:05:58 ylp 0.0 19 - futex_ - - 14063 00:00:00 ylp 0.0 19 - poll_s - - 14064 00:00:00 ylp 44.5 19 - - - - 14065 00:15:30 ylp 44.5 19 - - - - 14066 00:15:30 ylp 44.4 19 - - - - 14067 00:15:29 ylp 44.5 19 - - - - 14068 00:15:30 ylp 44.5 19 - - - - 14069 00:15:30 ylp 44.5 19 - - - - 14070 00:15:30 ylp 44.5 19 - - - - 14071 00:15:30 ylp 44.6 19 - - - - 14072 00:15:32 ylp 2.2 19 - futex_ - - 14073 00:00:46 ylp 0.0 19 - futex_ - - 14074 00:00:00 ylp 0.0 19 - futex_ - - 14075 00:00:00 ylp 0.0 19 - futex_ - - 14076 00:00:00 ylp 0.7 19 - futex_ - - 14077 00:00:15 從輸出資訊可以看出，14065~14072之間的線程CPU占用率都很高 2.3、檢視問題線程堆棧 挑選TID為14065的線程，檢視該線程的堆棧情況，先将線程id轉為16進制，使用printf "%x\n" tid指令進行轉換 [ylp@ylp-web-01 ~]$ printf "%x\n" 14065 36f1 再使用jstack指令列印線程堆棧資訊，指令格式：jstack pid |grep tid -A 30 [ylp@ylp-web-01 ~]$ 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指令檢視程序的記憶體情況 [ylp@ylp-web-01 ~]$ 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指令檢視程序的堆棧情況 [ylp@ylp-web-01 ~]$ jstack 14063 >>jstack.out 把jstack.out檔案從伺服器拿到本地後，用編輯器查找帶有項目目錄并且線程狀态是RUNABLE的相關資訊，從圖中可以看出ActivityUtil.java類的447行正在使用HashMap.put()方法 Paste_Image.png 3.3、代碼定位 打開項目工程，找到ActivityUtil類的477行，代碼如下： Paste_Image.png 找到相關同僚了解後，這段代碼會從資料庫中擷取配置，并根據資料庫中remain的值進行循環，在循環中會一直對HashMap進行put操作。 查詢資料庫中的配置，發現remain的數量巨大 Paste_Image.png 至此，問題定位完畢。

本文轉自快樂就好部落格園部落格，原文連結：http://www.cnblogs.com/happyday56/p/7154524.html，如需轉載請自行聯系原作者