java排查一個線上死循環(huán)cpu暴漲的過程分析

更新時間：2020年08月26日 10:57:29 作者：java的爪哇

這篇文章主要介紹了java排查一個線上死循環(huán)cpu暴漲的過程分析，具有很好的參考價值，希望對大家有所幫助。一起跟隨小編過來看看吧

問題，打一個頁面cpu暴漲，打開一次就漲100%,一會系統(tǒng)就卡的不行了。

排查方法，因為是線上的linux,沒有用jvm監(jiān)控工具rim鏈接上去。

只好用命令排查：

top cpu排序，一個java進程cpu到500%了，什么鬼.....

查到對應(yīng)java進程

jps || ps -aux | grep 端口

pid=13455

查看進程中線程使用情況 T排序查看cpu占用time最高的線程編號

top -Hp 13455

有個線程9877 的時間一直在爆漲

獲取線程十六進制地址9877 （十六進制一定要小寫）

printf "%x\n" 9877

執(zhí)行 jstack 13455|grep -10 2695（線程十六進制號）

如果想查看完整信息，可導出文本，查找

jstack -l 9839 > jstack.log-9893

"qtp750044075-25" #25 prio=5 os_prio=0 tid=0x00007f83354e5000 nid=0x2695 runnable [0x00007f830e5d8000]
 java.lang.Thread.State: RUNNABLE
at java.text.DateFormatSymbols.<init>(DateFormatSymbols.java:145)
at sun.util.locale.provider.DateFormatSymbolsProviderImpl.getInstance(DateFormatSymbolsProviderImpl.java:85)
at java.text.DateFormatSymbols.getProviderInstance(DateFormatSymbols.java:364)
at java.text.DateFormatSymbols.getInstance(DateFormatSymbols.java:340)
at java.util.Calendar.getDisplayName(Calendar.java:2110)
at java.text.SimpleDateFormat.subFormat(SimpleDateFormat.java:1125)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:966)
at java.text.SimpleDateFormat.format(SimpleDateFormat.java:936)
at java.text.DateFormat.format(DateFormat.java:345)
at com.huiwan.gdata.modules.gdata.util.TimeUtil.getDay(TimeUtil.java:383)
at com.huiwan.gdata.modules.gdata.publ.retain.service.impl.Retain3ServiceImpl.act(Retain3ServiceImpl.java:119)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
 .......略
 Locked ownable synchronizers:
- None

定住到

Retain3ServiceImpl.java:119

這行，馬的，有人寫了個while循環(huán)，用字符串時間比較，之前表是date類型，后改為datetime類型，多了00:00:00永遠也沒一樣的時間，一直在那while.....還搞了個json對象默認加0......

改了這里的代碼，就好了，cpu就沒上去了.

補充知識：記一次線上Java程序?qū)е路?wù)器CPU占用率過高的問題排除過程

1、故障現(xiàn)象

客服同事反饋平臺系統(tǒng)運行緩慢，網(wǎng)頁卡頓嚴重，多次重啟系統(tǒng)后問題依然存在，使用top命令查看服務(wù)器情況，發(fā)現(xiàn)CPU占用率過高。

2、CPU占用過高問題定位

2.1、定位問題進程

使用top命令查看資源占用情況，發(fā)現(xiàn)pid為14063的進程占用了大量的CPU資源，CPU占用率高達776.1%，內(nèi)存占用率也達到了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命令查看該進程的線程情況，發(fā)現(xiàn)該進程的多個線程占用率很高

[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轉(zhuǎn)為16進制，使用printf "%x\n" tid命令進行轉(zhuǎn)換

[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線程。此時可以基本確定是內(nèi)存不足或內(nèi)存泄露導致gc線程持續(xù)運行，導致CPU占用過高。

所以接下來我們要找的內(nèi)存方面的問題

3、內(nèi)存問題定位

3.1、使用jstat -gcutil命令查看進程的內(nèi)存情況

[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區(qū)內(nèi)存占用100%，Old區(qū)內(nèi)存占用99.99%，F(xiàn)ull GC的次數(shù)高達220次，并且頻繁Full GC，F(xiàn)ull GC的持續(xù)時間也特別長，平均每次Full GC耗時6.8秒（1505.439/220）。根據(jù)這些信息，基本可以確定是程序代碼上出現(xiàn)了問題，可能存在不合理創(chuàng)建對象的地方

3.2、分析堆棧

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