一醇滥、問題描述
Linux服務(wù)器的配置是4核16G识窿，將war包部署到tomcat后吹埠，啟動(dòng)tomcat第步，發(fā)現(xiàn)內(nèi)存占用率不高，但是CPU一直高達(dá)100%缘琅；瀏覽器輸入相關(guān)url也無法訪問該項(xiàng)目粘都，且tomcat的進(jìn)程一直存在，程序的配置什么的都沒問題啊刷袍，一頭霧水......通過top命令查看服務(wù)器的性能狀況如下：
[root@aws-java-MAM ec2-user]# top
top - 18:49:21 up 45 min, 2 users, load average: 0.97, 0.50, 0.19
Tasks: 129 total, 1 running, 128 sleeping, 0 stopped, 0 zombie
Cpu0 : 95.1%us, 0.0%sy, 0.0%ni, 4.9%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu1 : 5.9%us, 0.0%sy, 0.0%ni, 94.1%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 1.6%us, 0.5%sy, 0.0%ni, 97.8%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 1.1%us, 0.0%sy, 0.0%ni, 98.9%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 16330912k total, 2374776k used, 13956136k free, 20172k buffers
Swap: 0k total, 0k used, 0k free, 370244k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2141 root 20 0 7684m 1.7g 22m S 103.0 11.0 3:35.95 java
1423 root 20 0 449m 23m 2884 S 0.0 0.1 0:01.05 salt-minion
1959 root 20 0 98280 3860 2920 S 0.0 0.0 0:00.00 sshd
2278 root 20 0 98280 3836 2900 S 0.0 0.0 0:00.00 sshd
1387 postfix 20 0 81536 3436 2544 S 0.0 0.0 0:00.00 qmgr
1379 root 20 0 81284 3424 2520 S 0.0 0.0 0:00.01 master
1386 postfix 20 0 81364 3380 2508 S 0.0 0.0 0:00.00 pickup
1303 ntp 20 0 30720 2124 1508 S 0.0 0.0 0:00.00 ntpd
1986 root 20 0 105m 2000 1544 S 0.0 0.0 0:00.03 bash
1413 zabbix 20 0 42448 1972 1300 S 0.0 0.0 0:00.13 zabbix_agentd
可以看出PID為2141的java進(jìn)程耗費(fèi)內(nèi)存11%翩隧，不算高，但是CPU達(dá)到103%呻纹，應(yīng)該是哪里出現(xiàn)了死循環(huán)或者線程阻塞住了堆生，導(dǎo)致CPU占用居高不下（各種配置個(gè)人覺得應(yīng)該是沒問題的），怎么定位到具體線程或者程序位置呢雷酪？想到了jstack工具淑仆。
二、jstack簡(jiǎn)介
jstack是java虛擬機(jī)自帶的一種堆棧跟蹤工具哥力。用于打印出給定的java進(jìn)程ID或core file或遠(yuǎn)程調(diào)試服務(wù)的Java堆棧信息蔗怠，使用jstack命令工具可以得到線程堆棧信息墩弯，根據(jù)這些線程堆棧信息，我們可以去檢查Java程序出現(xiàn)的問題寞射，如檢測(cè)死鎖渔工，并輸出死鎖的信息的排查。
三桥温、排查方式
1引矩、首先通過如下命令顯示線程列表
ps -mp pid -o THREAD,tid,time
[root@aws-java-MAM ec2-user]# ps -mp 2141 -o THREAD,tid,time |sort -rn
USER %CPU PRI SCNT WCHAN USER SYSTEM TID TIME
root 94.3 - - - - - - 00:04:04
root 85.9 19 - - - - 2185 00:03:21
root 3.7 19 - futex_ - - 2153 00:00:09
root 3.6 19 - futex_ - - 2152 00:00:09
root 2.8 19 - futex_ - - 2162 00:00:07
root 1.3 19 - futex_ - - 2154 00:00:03
root 0.9 19 - futex_ - - 2176 00:00:02
root 0.7 19 - futex_ - - 2147 00:00:02
root 0.7 19 - futex_ - - 2146 00:00:02
root 0.7 19 - futex_ - - 2145 00:00:02
root 0.7 19 - futex_ - - 2144 00:00:02
root 0.2 19 - futex_ - - 2148 00:00:00
root 0.2 19 - futex_ - - 2143 00:00:00
root 0.1 19 - inet_s - - 2209 00:00:00
root 0.0 19 - poll_s - - 2181 00:00:00
root 0.0 19 - poll_s - - 2179 00:00:00
root 0.0 19 - futex_ - - 2188 00:00:00
root 0.0 19 - futex_ - - 2183 00:00:00
root 0.0 19 - futex_ - - 2182 00:00:00
root 0.0 19 - futex_ - - 2180 00:00:00
root 0.0 19 - futex_ - - 2178 00:00:00
root 0.0 19 - futex_ - - 2175 00:00:00
從這里可以看出最耗CPU的線程ID是2185，占用CPU85.9%策治，TIME對(duì)應(yīng)的是時(shí)間脓魏，持續(xù)了3分21秒鐘了，命令中的sort -rn是倒序排序的意思通惫。
2、將需要的線程ID轉(zhuǎn)換為16進(jìn)制格式
printf "%x\n" tid
[root@aws-java-MAM ec2-user]# printf "%x\n" 2185
889
3混蔼、打印線程的堆棧信息
jstack pid |grep tid -A 100
[root@aws-java-MAM ec2-user]# jstack 2141 |grep 889 -A 100
"Common.timer" #39 daemon prio=5 os_prio=0 tid=0x00007ffbc4398800 nid=0x889 runnable [0x00007ffc49b19000]
java.lang.Thread.State: RUNNABLE
at com.skymusic.service.cache.Cache$1.run(Cache.java:59)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)
"Timer-1" #37 daemon prio=5 os_prio=0 tid=0x00007ffbc4373800 nid=0x887 in Object.wait() [0x00007ffc49c1a000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000006c8201a40> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"pool-4-thread-2" #36 prio=5 os_prio=0 tid=0x00007ffbc41f9800 nid=0x886 waiting on condition [0x00007ffc49f1b000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006cb893460> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"AMQP Connection 172.31.44.144:5672" #35 prio=5 os_prio=0 tid=0x00007ffbc41f8000 nid=0x885 runnable [0x00007ffc4a01c000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <0x00000006cb893a28> (a java.io.BufferedInputStream)
at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:288)
at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:91)
at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:164)
- locked <0x00000006cb893a08> (a java.io.DataInputStream)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:596)
at java.lang.Thread.run(Thread.java:745)
"pool-2-thread-2" #34 prio=5 os_prio=0 tid=0x00007ffbc41f6800 nid=0x884 waiting on condition [0x00007ffc4a11d000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006cbca2378> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
"AMQP Connection 172.31.41.147:5672" #33 prio=5 os_prio=0 tid=0x00007ffbc41ef000 nid=0x883 runnable [0x00007ffc4a21e000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
- locked <0x00000006cbcb8b60> (a java.io.BufferedInputStream)
at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:288)
at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:91)
at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:164)
- locked <0x00000006cbcb8b40> (a java.io.DataInputStream)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:596)
at java.lang.Thread.run(Thread.java:745)
"Timer-0" #32 daemon prio=5 os_prio=0 tid=0x00007ffbf8f94800 nid=0x882 in Object.wait() [0x00007ffc4aad1000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x00000006cbcc2d48> (a java.util.TaskQueue)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000006cbcc2d48> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"Thread-7" #30 daemon prio=5 os_prio=0 tid=0x00007ffbf8f90800 nid=0x880 waiting on condition [0x00007ffc4b0f3000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c8160e18> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at com.dj.boot.Boot.init(Boot.java:108)
at com.dj.boot.Boot.dev(Boot.java:35)
at com.dj.filter.MD5Filter$1.run(MD5Filter.java:65)
at java.lang.Thread.run(Thread.java:745)
"startQuertz_QuartzSchedulerThread" #29 prio=5 os_prio=0 tid=0x00007ffbf8f77800 nid=0x87f in Object.wait() [0x00007ffc4b1f4000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at org.quartz.core.QuartzSchedulerThread.run(QuartzSchedulerThread.java:410)
- locked <0x00000006c7dbf6b0> (a java.lang.Object)
"startQuertz_Worker-10" #28 prio=5 os_prio=0 tid=0x00007ffbf8f6c000 nid=0x87e in Object.wait() [0x00007ffc4b2f5000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
[root@aws-java-MAM ec2-user]#
-A后面的參數(shù)是行數(shù)履腋，顯示多少行堆棧信息，100就是顯示100行惭嚣。其中以下部分的內(nèi)容引起了我的關(guān)注：
"Thread-7" #30 daemon prio=5 os_prio=0 tid=0x00007ffbf8f90800 nid=0x880 waiting on condition [0x00007ffc4b0f3000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000006c8160e18> (a java.util.concurrent.CountDownLatch$Sync)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:997)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1304)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:231)
at com.dj.boot.Boot.init(Boot.java:108)
at com.dj.boot.Boot.dev(Boot.java:35)
at com.dj.filter.MD5Filter$1.run(MD5Filter.java:65)
at java.lang.Thread.run(Thread.java:745)
這里有個(gè)MD5Filter類的run方法遵湖，起了一個(gè)線程去初始化一個(gè)Boot配置（其他同事新增的業(yè)務(wù)，不了解）晚吞，然后一直在這里WATTING了延旧，于是找了相關(guān)同事看了一下，發(fā)現(xiàn)新增的業(yè)務(wù)邏輯有問題槽地，同事改了之后CPU就下來了迁沫。
4、再總結(jié)下排查CPU故障的方法和技巧
1）top命令
查看實(shí)時(shí)的CPU使用情況捌蚊，也可以查看最近一段時(shí)間的CPU使用情況集畅。
2）PS命令
進(jìn)程狀態(tài)監(jiān)控命令；可以查看進(jìn)程以及進(jìn)程中線程的當(dāng)前CPU使用情況缅糟，屬于當(dāng)前狀態(tài)的采樣數(shù)據(jù)挺智。
3）jstack
查看某個(gè)進(jìn)程的當(dāng)前線程棧運(yùn)行情況。根據(jù)這個(gè)命令的輸出可以定位某個(gè)進(jìn)程的所有線程的當(dāng)前運(yùn)行狀態(tài)窗宦、運(yùn)行代碼赦颇，以及是否死鎖等。
4）pstack
查看某個(gè)進(jìn)程的當(dāng)前線程棧運(yùn)行情況赴涵。
