您的位置 首页 java

JVM堆栈分析方法论，以后JAVA环境出问题就用它

智云科技发布于 2023年1月5日评论关闭阅读(226)

JAVA

JMX简单定义

JMX（Java Management Extensions，即Java管理扩展）是Java平台上为应用程序、设备、系统等植入管理功能的框架。用户可以在任何Java应用程序中使用这些代理和服务实现管理。

JMX架构简图

JMX架构

JMX的结构一共分为三层：

  • 基础层：主要是MBean，被管理的资源。
  • 适配层：MBeanServer，主要是提供对资源的注册和管理。
  • 接入层：提供远程访问的入口。

JMX堆栈分析

线程堆栈定义

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

  • 线程名字，id，线程的数量等。
  • 线程的运行状态，锁的状态（锁被哪个线程持有，哪个线程在等待锁等）
  • 调用堆栈（即函数的调用层次关系）调用堆栈包含完整的类名，所执行的方法，源代码的行数。

堆栈可以解决的问题

借助堆栈信息可以帮助分析很多问题，如线程 死锁 ，锁争用，死循环，识别耗时操作等等。在多线程场合下的稳定性问题分析和性能问题分析，线程堆栈分析湿最有效的方法，在多数情况下，无需对系统了解就可以进行相应的分析。

由于线程堆栈是系统某个时刻的线程运行状况（即瞬间快照），对于历史痕迹无法追踪。只能结合日志分析。总的来说线程堆栈是多线程类应用程序非功能型问题定位的最有效手段，最善于分析如下类型问题：

  • 系统无缘无故的cpu过高
  • 系统挂起，无响应
  • 系统运行越来越慢
  • 性能瓶颈（如无法充分利用cpu等）
  • 线程死锁，死循环等
  • 由于线程数量太多导致的内存溢出（如无法创建线程等）

死锁定义

死锁是线程竞争的一个特殊状态，一个或是多个线程在等待其他线程完成它们的任务。

堆栈线程状态

  • 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 >> 文件

option参数:

-F:当正常输出请求不响应时，强制输出线程堆栈

-l:除堆栈外，显示关于锁的附加信息

-m:如果调用到本地方法的话，可以显示C/C++堆栈

JMX堆栈信息解读

RUNNABLE状态示例

一般来讲，我们只需要关注处于RUNNABLE状态的线程并且包含com.xxx的一行(从下往上看，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.CallServer intercept or.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.xxx.xxx.scan.dinner.service.impl.CouponsServiceImpl.queryCouponLimitRuleList(CouponsServiceImpl.java:478)
 at com.xxx.xxx.scan.dinner.controller.CouponsController.queryCouponLimitRuleList(CouponsController.java:115)
 at com.xxx.xxx.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

线程解读：

  1. 线程名,“http-nio-40243-exec-10”
  2. 线程属性（如果是Daemon线程，会有Daemon标识，否则，什么都没有）
  3. 线程优先级，prio
  4. java线程对应的本地线程的优先级os_prio
  5. java线程标识tid
  6. java线程对应的本地线程标识nid
  7. 线程状态（运行中、等待等）
  8. 线程的栈信息
  9. 线程锁信息

从线程的调用上下文可以看到从哪个函数调用到哪个函数，正执行到哪一类的哪一行。

方法

示例中基本可以定位到出现问题的方法为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.Writer append er.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虚拟机有不同的实现策略，不一定会立刻响应请求，也许会等待正在执行的线程执行完成。

生产中的问题

实际环境中，我们通常会遇到两类问题，一类是CPU高，程序响应慢，另一类是CPU正常，但是系统性能比较差，同时可能繁忙线程高。

CPU高，程序响应慢

1）top命令获取占用CPU最高的程序PID，此例为21382

top

2）找到此进程中消耗CPU较高的线程ID

top -Hp

3)将线程ID转换为16进制

printf “%x\n”

4）使用jstack打印堆栈信息 

$ jstack -l 21382 >21382.log

5）在堆栈结果中查询16进制

堆栈结果

结果中可能会出现三种情况:

情况一：直接打印出代码类名，这种情况就很好定位是代码的问题，优化代码即可

情况二：”C2 CompilerThread*”开头的堆栈信息，此信息表示java编译的线程，说明java编译器编译过于频繁，tomcat程序则加上参数 -XX:CICompilerCount=4 此设置表示改变编译器线程为4线程并行处理

情况三：”catalina-exec-***”开头的堆栈信息，此信息表示程序正常处理的线程，则表示程序本身有待优化

基本思路只需要关注处于RUNNABLE状态的线程并且包含com.xxx的一行即可(从下往上看)

注：由于环境并未出现问题，所以此处状态正常，参考思路即可

CPU正常，但是系统性能比较差，同时可能繁忙线程高

这种情况，出现阻塞线程的可能性比较大，需要多次dump来抓取BLOCKED 状态的线程列表。

后记

目前大部分公司开发语言还是以JAVA为主，多以了解下 JVM 对于解决问题还是很有帮助的。如果说系统慢，那么要特别关注Blocked,Waiting on condition状态的线程。如果说系统的cpu耗的高，那么肯定是线程执行有死循环，那么此时要关注下Runable状态的线程。

标签:
打赏 点赞(1)

文章来源：智云一二三科技

文章标题：JVM堆栈分析方法论，以后JAVA环境出问题就用它

文章地址：https://www.zhihuclub.com/173438.shtml

关于作者: 智云科技

相关文章

热门文章

1分享新浪图床上传接口源码

点赞(972)阅读(61,528)

2PHP简单实现路由Route功能

点赞(1.19K)阅读(35,991)

3Tideways、xhprof 和 xhgui 打造 PHP 非侵入式监控平台

点赞(411)阅读(4,323)

4centos系统如何查看是否安装了mysql

点赞(577)阅读(3,812)

5curl 工具简述

点赞(567)阅读(3,002)
网站地图