JMX堆栈分析

Posted 2020-12-30 aresxin

线程堆栈：

线程堆栈也称线程调用堆栈，是虚拟机中线程（包括锁）状态的一个瞬间快照，即系统在某一个时刻所有线程的运行状态，包括每一个线程的调用堆栈，锁的持有情况。虽然不同的虚拟机打印出来的格式有些不同，但是线程堆栈的信息都包含：

• 线程名字，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

View Code

线程解读：

• 线程名,“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)

View Code

上面的示例中，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 " 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.