JMX堆棧分析

線程堆棧：

線程堆棧也稱線程調用堆棧，是虛擬機中線程（包括鎖）狀態的一個瞬間快照，即系統在某一個時刻所有線程的運行狀態，包括每一個線程的調用堆棧，鎖的持有情況。雖然不同的虛擬機打印出來的格式有些不同，但是線程堆棧的信息都包含：

• 線程名字，id，線程的數量等。
• 線程的運行狀態，鎖的狀態（鎖被哪個線程持有，哪個線程在等待鎖等）
• 調用堆棧（即函數的調用層次關系）調用堆棧包含完整的類名，所執行的方法，源代碼的行數。

借助堆棧信息可以幫助分析很多問題，如線程死鎖，鎖爭用，死循環，識別耗時操作等等。在多線程場合下的穩定性問題分析和性能問題分析，線程堆棧分析濕最有效的方法，在多數情況下，無需對系統了解就可以進行相應的分析。
由於線程堆棧是系統某個時刻的線程運行狀況（即瞬間快照），對於歷史痕跡無法追蹤。只能結合日志分析。總的來說線程堆棧是多線程類應用程序非功能型問題定位的最有效手段，最善於分析如下類型問題：

• 系統無緣無故的cpu過高
• 系統掛起，無響應
• 系統運行越來越慢
• 性能瓶頸（如無法充分利用cpu等）
• 線程死鎖，死循環等
• 由於線程數量太多導致的內存溢出（如無法創建線程等）

死鎖：

一個 web 服務器使用幾十到幾百個線程來處理大量並發用戶，如果一個或多個線程使用相同的資源，線程之間的競爭就不可避免了，並且可能會發生死鎖。

死鎖是線程競爭的一個特殊狀態，一個或是多個線程在等待其他線程完成它們的任務。

線程狀態：

• NEW：線程剛被創建，但是還沒有被處理。
• RUNNABLE：當調用thread.start()后，線程變成為Runnable狀態。只要得到CPU，就可以執行
• Running：線程正在執行
• BLOCKED：該線程正在等待另外的不同的線程釋放鎖，阻塞狀態
• WAITING：該線程正在等待，通過使用了 wait, join 或者是 park 方法
• TIMED_WAITING：該線程正在等待，通過使用了 sleep, wait, join 或者是 park 方法，與Waiting的區別在於Timed_Waiting的等待有時間限制
• Dead：線程執行完畢，或者拋出了未捕獲的異常之后，會進入dead狀態，表示該線程結束

輸出堆棧：

通常將堆棧信息重定向到一個文件中，

命令 : $jstack [option] pid >> 文件  

堆棧解讀：

只需要關注java用戶線程，其他由虛擬機自動創建的，在實際分析中可以暫時忽略：

一般來講，我們只需要關注處於RUNNABLE狀態的線程並且包含com.xxx的一行(從下往上看)

"http-nio-40243-exec-9" #125 daemon prio=5 os_prio=0 tid=0x00007fd234d9f800 nid=0x7114 runnable [0x00007fd194e87000]
   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 okio.Okio$2.read(Okio.java:139)
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:237)
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:345)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:217)
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:211)
        at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189)
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:75)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45)
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:92)
        xxxxxxxxxxxxxxxx
        at feign.ReflectiveFeign$FeignInvocationHandler.invoke(ReflectiveFeign.java:103)
        at com.sun.proxy.$Proxy176.getCampaignShopCouponLimitRule(Unknown Source)
        at com.yazuo.kbpos.scan.dinner.service.impl.CouponsServiceImpl.queryCouponLimitRuleList(CouponsServiceImpl.java:478)
        at com.yazuo.kbpos.scan.dinner.controller.CouponsController.queryCouponLimitRuleList(CouponsController.java:115)
        at com.yazuo.kbpos.scan.dinner.controller.CouponsController$$FastClassBySpringCGLIB$$95e09cc2.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:738

線程解讀：

• 線程名,“http-nio-40243-exec-10”
• 線程屬性（如果是Daemon線程，會有Daemon標識，否則，什么都沒有）
• 線程優先級，prio
• java線程對應的本地線程的優先級os_prio
• java線程標識tid
• java線程對應的本地線程標識nid
• 線程狀態（運行中、等待等）
• 線程的棧信息
• 線程鎖信息

線程堆棧里面的最直觀的信息是當前線程的調用上下文，即從哪個函數調用到哪個函數（從下往上看），正執行到哪一類的哪一行，借助這些信息，我們就對當前系統正在做什么一目了然。

示例中基本可以定位到出現問題的方法為getCampaignShopCouponLimitRule

 

BLOCKED狀態示例：

 折疊源碼
"http-nio-40243-exec-393" #1212 daemon prio=5 os_prio=0 tid=0x00007f4fdc3d9000 nid=0xe30 runnable [0x00007f4fc09d0000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.Throwable.getStackTraceElement(Native Method)
        at java.lang.Throwable.getOurStackTrace(Throwable.java:827)
        - locked <0x00000000faf1f990> (a java.lang.Throwable)
        at java.lang.Throwable.getStackTrace(Throwable.java:816)
        at sun.reflect.GeneratedMethodAccessor2.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:497)
        at org.apache.log4j.spi.LocationInfo.<init>(LocationInfo.java:139)
        at org.apache.log4j.spi.LoggingEvent.getLocationInformation(LoggingEvent.java:253)
        at org.apache.log4j.pattern.LineLocationPatternConverter.format(LineLocationPatternConverter.java:58)
        at org.apache.log4j.pattern.BridgePatternConverter.format(BridgePatternConverter.java:119)
        at org.apache.log4j.EnhancedPatternLayout.format(EnhancedPatternLayout.java:546)
        at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:310)
        at org.apache.log4j.WriterAppender.append(WriterAppender.java:162)
        at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
        - locked <0x00000000e00a2d40> (a org.apache.log4j.ConsoleAppender)
        at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
        at org.apache.log4j.Category.callAppenders(Category.java:206)
        - locked <0x00000000e009adf0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        XXXXXXXXXXXXXX
"http-nio-40243-exec-392" #1211 daemon prio=5 os_prio=0 tid=0x00007f4fd8095000 nid=0xe2f waiting for monitor entry [0x00007f4fc0dd4000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.apache.log4j.Category.callAppenders(Category.java:204)
        - waiting to lock <0x00000000e009adf0> (a org.apache.log4j.Logger)
        at org.apache.log4j.Category.forcedLog(Category.java:391)
        at org.apache.log4j.Category.log(Category.java:856)
        at org.slf4j.impl.Log4jLoggerAdapter.debug(Log4jLoggerAdapter.java:230)
        at com.navercorp.pinpoint.profiler.logging.Slf4jPLoggerAdapter.debug(Slf4jPLoggerAdapter.java:285)
        at com.navercorp.pinpoint.plugin.redis.interceptor.ProtocolSendCommandAndReadMethodInterceptor.before(ProtocolSendCommandAndReadMethodIntercept
or.java:71)

上面的示例中，http-nio-40243-exec-393線程占用了<0x00000000e009adf0>鎖，然而http-nio-40243-exec-392正在等待獲取鎖。

• 當一個線程占有一個鎖的時候，線程堆棧會打印一個－locked
• 當一個線程正在等在其他線程釋放該鎖，線程堆棧會打印一個－waiting to lock
• 當一個線程占有一個鎖，但又執行在該鎖的wait上，線程堆棧中首先打印locked,然后打印－waiting on

一般情況下，當一個或一些線程正在等待一個鎖的時候，應該有一個線程占用了這個鎖，即如果有一個線程正在等待一個鎖，該鎖必然被另一個線程占用，從線程堆棧中看，如果看到waiting to lock<0x22bffb60>,應該也應該有locked<0x22bffb60>,大多數情況下確實如此，但是有些情況下，會發現線程堆棧中可能根本沒有locked<0x22bffb60>,而只有waiting to ，這是什么原因呢，實際上，在一個線程釋放鎖和另一個線程被喚醒之間有一個時間窗，如果這個期間，恰好打印堆棧信息，那么只會找到waiting to ，但是找不到locked 該鎖的線程，當然不同的JAVA虛擬機有不同的實現策略，不一定會立刻響應請求，也許會等待正在執行的線程執行完成。

現實場景中，一般遇到的都是兩類問題：

1、CPU高，程序響應慢

1）TOP命令獲取占用CPU最高的程序PID

2）找到此進程中消耗CPU較高的線程ID

# top -Hp 2093

在上圖TIME+列，表示為消耗CPU時間。如圖得出消耗時間較長的線程ID為：2163 2094

3）將線程ID轉換為16進制

# printf "%x\n" 2163

4）使用jstack打印堆棧信息

$ jstack  -l 2093 >2093.log

5）結果中查詢

情況一：直接打印出代碼類名，這種情況就很好定位是代碼的問題，優化代碼即可

情況二："C2 CompilerThread*"開頭的堆棧信息，此信息表示java編譯的線程，說明java編譯器編譯過於頻繁，tomcat程序則加上參數 -XX:CICompilerCount=4 此設置表示改變編譯器線程為4線程並行處理

情況三："catalina-exec-***"開頭的堆棧信息，此信息表示程序正常處理的線程，則表示程序本身有待優化

基本思路只需要關注處於RUNNABLE狀態的線程並且包含com.xxx的一行即可(從下往上看)

 

2、CPU正常，但是系統性能比較差，同時可能繁忙線程高

此時需要多次dump，然后找出 BLOCKED 狀態的線程列表。

總結：

如果說系統慢，那么要特別關注Blocked,Waiting on condition
如果說系統的cpu耗的高，那么肯定是線程執行有死循環，那么此時要關注下Runable狀態。

備注：

1.處於RUNNABLE狀態的線程不一定會消耗cpu，像socket IO操作，線程正在從網絡上讀取數據，盡管線程狀態RUNNABLE，但實際上網絡io，線程絕大多數時間是被掛起的，只有當數據到達后，線程才會被喚起，掛起發生在本地代碼（native）中，虛擬機無法知道真正的線程狀態，因此一概顯示為RUNNABLE。如果是純java運算代碼，則消耗cpu，如果網絡io，很少消耗cpu。

2.處於timed_waiting,waiting狀態的線程一定不消耗cpu.