线程堆栈信息以及解决的问题

1、线程堆栈的信息都包含:

• 线程的名字，ID，线程的数量等。
• 线程的运行状态，锁的状态(锁被哪个线程持有，哪个线程再等待锁等)。
• 调用堆栈(函数的调用层次关系)。调用堆栈包含完整的类名，执行的方法，源代* 码的行数。具体打印出的堆栈信息依赖于你的系统的复杂程度。

2、通过线程堆栈可以解决的问题

• 无缘无故CPU过高
• 系统挂起，无响应
• 系统运行越来越慢（资源争用或者锁竞争）
• 线程死锁问题
• 由于线程数量太多导致系统失败(如无法创建线程等)。

如何输出线程堆栈

1、如果获取堆栈日志

JVM虚拟机提供了线程转储的后门，通过后门可以将线程堆栈打印出来，通过这个后门向指定的Java进程发送一个QUIT信号，Java虚拟机收到信号以后就会打印出进程的堆栈信息。一般我们会将日志信息重定向到文件中。

jstack [option] pid >> jstack.info

jstack命令使用如下：

jstack [option] pid
--参数
1. -F 强制打印堆栈

2. -m 打印java 和 native（C++） 堆栈信息  

3. -l 打印额外的信息，包括锁信息

要打印堆栈日志，首先要获取java应用的进程号：

命令一：jps
命令二：ps -ef | grep java

解读线程堆栈

1、堆栈日志

下面是某个线程的堆栈日志：

"com.sankuai.sjst.scm.purchase.service.order.OrderReadThriftService-7-thread-3" #214 daemon prio=5 os_prio=0 tid=0x00007fd406b5b000 nid=0x7a4c waiting for monitor entry [0x00007fd30fffc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.io.PrintStream.println(PrintStream.java:805)
    - waiting to lock <0x00000000c3b916f8> (a java.io.PrintStream)
    at org.apache.ibatis.logging.stdout.StdOutImpl.trace(StdOutImpl.java:50)
    at org.apache.ibatis.logging.jdbc.BaseJdbcLogger.trace(BaseJdbcLogger.java:145)
    at org.apache.ibatis.logging.jdbc.ResultSetLogger.printColumnValues(ResultSetLogger.java:123)
    at org.apache.ibatis.logging.jdbc.ResultSetLogger.invoke(ResultSetLogger.java:78)
    at com.sun.proxy.$Proxy111.next(Unknown Source)
    at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValuesForSimpleResultMap(DefaultResultSetHandler.java:292)
    at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleRowValues(DefaultResultSetHandler.java:269)
    at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSet(DefaultResultSetHandler.java:239)
    at org.apache.ibatis.executor.resultset.DefaultResultSetHandler.handleResultSets(DefaultResultSetHandler.java:153)
    at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:60)
    at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:73)
    at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:60)
    at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:267)
    at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:137)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:96)
    at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:77)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:108)
    at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:102)
    at sun.reflect.GeneratedMethodAccessor70.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:386)
    at com.sun.proxy.$Proxy51.selectList(Unknown Source)
    at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:205)
    at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:119)
    at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:63)
    at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:52)
    at com.sun.proxy.$Proxy62.listFullDetailsByOrderSn(Unknown Source)
    at sun.reflect.GeneratedMethodAccessor288.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.dianping.zebra.dao.AsyncMapperProxy.invoke(AsyncMapperProxy.java:66)
    at com.sun.proxy.$Proxy62.listFullDetailsByOrderSn(Unknown Source)
    at com.sankuai.sjst.scm.purchase.service.order.impl.PurchaseOrderDetailServiceImpl.listOrderFullDetailByOrderSn(PurchaseOrderDetailServiceImpl.java:127)
    at sun.reflect.GeneratedMethodAccessor287.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:333)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:190)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:157)
    at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:96)
    at com.sankuai.sjst.scm.purchase.aspect.ServiceCostLog.timeAround(ServiceCostLog.java:37)
    at sun.reflect.GeneratedMethodAccessor138.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:627)
    at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:616)

从上面的线程堆栈信息中可以直观的看出当前线程的调用上下文，从哪个函数调用到哪个函数（扩展：调用堆栈是从下往上看，可以思考一下为什么？？？）

2、线程信息

image.png

Java语言中的线程是依附于操作系统的线程来运行的，从本质上来说是本地线程在执行java线程代码，从JVM源码角度分析，在Java中创建线程是，实际上创建一个os thread，这个os才是真正的线程实体。

关于jvm虚拟机线程创建感兴趣的可以参考该链接：https://www.jianshu.com/p/3ce1b5e5a55e

• 线程名称：线程创建的时候，设置的线程名称，建议创建的线程都自定义线程的名称，通过线程名称可以知道该线程是处理什么任务
• 守护进程：创建线程的时候可以设置线程是否是守护进程。
• 优先级：线程创建的时候设置线程的优先级，一般采用默认值
• 线程id（tid）：JVM给线程分配的id号
• 本地线程id（nid）：对应的os 线程的线程id，可以将16进制转换为10进制，在os中找到对应的线程
• 线程状态：这线程堆栈日志中，一个线程就waiting 状态和 runnale两种状态
• 线程内存地址：线程起始地址

3、线程状态

当看见线程是runnable状态时，线程不一定真正的消耗cpu，出于Runnable状态的线程只能说没有阻塞到java的wait或者sleep方法上，同时也没有在进行锁等待，

如果该线程调用了本地方法，该本地方法处于等待状态，这个时候虚拟机不知道本地代码中发生了什么，所以尽管线程已经阻塞了，但是显示出来的状态还是runnable。

堆栈信息如下：

"NettyBossSelector_1" #331 prio=5 os_prio=0 tid=0x00007fd405f7c000 nid=0x7a90 runnable [0x00007fd2fbffe000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)    //调用本地方法的的epollWait方法，此时线程阻塞，但是日志打印出来的状态是runnable
    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
    - locked <0x00000000c4b04bf8> (a io.netty.channel.nio.SelectedSelectionKeySet)
    - locked <0x00000000c4b04be8> (a java.util.Collections$UnmodifiableSet)
    - locked <0x00000000c4b04ba0> (a sun.nio.ch.EPollSelectorImpl)
    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:310)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
    at java.lang.Thread.run(Thread.java:745)

上面epollWait调用了本地方法，其实没有在消耗cpu；只有线程正在执行Java的指令时，才是真正的在消耗cpu。

4、调用堆栈

image.png

5、锁信息

image.png

6、锁解读

在java中，提供wait（）方法和sleep（）方法，二者有一个共同点，就是阻塞当前线程，但是调用wait方法或释放持有的锁，等待其他线程调用notify方法，才能被唤醒，进行锁的竞争。

调用sleep方法不会释放锁，只是让线程让出cpu。

当一个(些)线程在等待一个锁时，应该有一个线程占用这个锁，即如果有的线程在等待一个锁，该锁必然被另一个线程占有了，也就是说，从打印的堆栈中如果能看到waiting to lock <0x22bffb60>,应该也应该能找到一个线程locked <0x22bffb60>

在之前的线程堆栈信息中可以看出线程的调用方法栈，线程的锁信息，在日志中一般会出现下面三种锁日志信息：

• 当一个线程占有一个锁的时候，线程堆栈中会打印—locked <0x22bffb60>

• 当一个线程正在等待其它线程释放该锁，线程堆栈中会打印—waiting to lock <0x22bffb60>

• 当一个线程占有一个锁，但又执行到该锁的wait()上，线程堆栈中首先打印locked,然后又会打印—waiting on <0x22c03c60>

线程堆栈中与锁相关的三个最重要的特征字:locked,waiting to lock,waiting on,了解这三个特征字，就能够对锁进行分析了

7、Java线程状态

在线程堆栈日志中，会打印java.lang.Thread.State，这个字段的状态信息，与java里面线程状态定义对应

image.png

• RUNNABLE： 表示线程正在运行，在执行本地方法的时候不一定消耗cpu

• TIMED_WAITING（parking）：表示当前线程被挂起，调用了LockSupport.parkNanos(blocker,time)等方法

"jetty-worker-18" #18 prio=5 os_prio=0 tid=0x00007fd4049c5800 nid=0x789a waiting on condition [0x00007fd3a9037000]
   java.lang.Thread.State: TIMED_WAITING (parking)
    at sun.misc.Unsafe.park(Native Method)
    - parking to wait for  <0x00000000c1e3cb10> (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 org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:389)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:522)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.access$700(QueuedThreadPool.java:47)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:581)
    at java.lang.Thread.run(Thread.java:745)

• TIMED_WAITING(on object monitor)：表示当前线程被挂起一段时间,说明该线程正在执行obj.wait(int time)方法

"com.sankuai.mms.util.MtRolloverFileOutputStream" #15 daemon prio=5 os_prio=0 tid=0x00007fd404676000 nid=0x7893 in Object.wait() [0x00007fd3c41f3000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x00000000c1e44c38> (a java.util.TaskQueue)
    at java.util.TimerThread.mainLoop(Timer.java:552)
    - locked <0x00000000c1e44c38> (a java.util.TaskQueue)
    at java.util.TimerThread.run(Timer.java:505)

• TIMED_WAITING (sleeping)：表示当前线程正在被挂起一段时间，一般是在执行Thread.sleep(int time)

"cat-netty-channel-health-check" #78 daemon prio=5 os_prio=0 tid=0x00007fd40473a000 nid=0x7979 waiting on condition [0x00007fd31fbfe000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at com.dianping.cat.message.io.ChannelManager.run(ChannelManager.java:382)
    at java.lang.Thread.run(Thread.java:745)
    at com.dianping.cat.util.Threads$RunnableThread.run(Threads.java:289)

• WAINTING(on object monitor)：当前线程被挂起，即正在执行obj.wait()方法(无参数的wait()方法)，只能通过notify方法唤醒

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007fd404248000 nid=0x7881 in Object.wait() [0x00007fd3c5524000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)
    - locked <0x00000000c1e45c58> (a java.lang.ref.Reference$Lock)

• BLOCKED（on object monitor）：表示线程真正等待一个对象锁，（一般出现在竞争公共资源的时候）如果获得了对象锁，进入synchronized对象块。waiting for monitor entry 说明此线程通过 synchronized(obj) {……} 申请进入了临界区，从而进入了“Entry Set”队列，但该 obj 对应的 monitor 被其他

"com.sankuai.sjst.scm.purchase.service.order.OrderReadThriftService-7-thread-3" #214 daemon prio=5 os_prio=0 tid=0x00007fd406b5b000 nid=0x7a4c waiting for monitor entry [0x00007fd30fffc000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.io.PrintStream.println(PrintStream.java:805)
    - waiting to lock <0x00000000c3b916f8> (a java.io.PrintStream)
    at org.apache.ibatis.logging.stdout.StdOutImpl.trace(StdOutImpl.java:50)
    at org.apache.ibatis.logging.jdbc.BaseJdbcLogger.trace(BaseJdbcLogger.java:145)

四、如何借助线程堆栈进行问题分析

1、从一次堆栈信息中，我们能够获取到什么

• 每个线程的调用上下文
• 当前线程正在执行的函数
• 当前每个线程当前的状态
• 当前现在持有的锁，等待的锁，以及锁争用信息

2、如何定位消耗cpu最高的线程

• 获取进程id

方案一：jps
方案二：ps -ef | grep java
方案三：top

• 获取线程消耗cpu最多的线程
  可以通过top -Hp <pid>来看这个进程里所有线程的cpu消耗情况

top -Hp <pid>

上面获取到了最耗cpu的线程的id，但是是10进制，将10进制转换为16进制，在导出的堆栈信息中找到对应的线程，查看线程堆栈信息.

https://github.com/oldratlee/useful-scripts/blob/master/docs/java.md#-show-busy-java-threads 查询耗cpu最高的线程

3、线程死锁

image.png

4、资源不足

之前看到大量查询现在被阻塞到 ibatis方法的调用中，这个时候可以分析一下是否是因为连接池的原因。