線程堆棧信息以及解決的問題

1必逆、線程堆棧的信息都包含:

• 線程的名字怠堪，ID揽乱，線程的數(shù)量等。
• 線程的運(yùn)行狀態(tài)粟矿，鎖的狀態(tài)(鎖被哪個(gè)線程持有凰棉，哪個(gè)線程再等待鎖等)。
• 調(diào)用堆棧(函數(shù)的調(diào)用層次關(guān)系)陌粹。調(diào)用堆棧包含完整的類名撒犀，執(zhí)行的方法，源代* 碼的行數(shù)掏秩。具體打印出的堆棧信息依賴于你的系統(tǒng)的復(fù)雜程度或舞。

2、通過線程堆椕苫茫可以解決的問題

• 無緣無故CPU過高
• 系統(tǒng)掛起映凳，無響應(yīng)
• 系統(tǒng)運(yùn)行越來越慢（資源爭(zhēng)用或者鎖競(jìng)爭(zhēng)）
• 線程死鎖問題
• 由于線程數(shù)量太多導(dǎo)致系統(tǒng)失敗(如無法創(chuàng)建線程等)。

如何輸出線程堆棧

1邮破、如果獲取堆棧日志

JVM虛擬機(jī)提供了線程轉(zhuǎn)儲(chǔ)的后門诈豌，通過后門可以將線程堆棧打印出來，通過這個(gè)后門向指定的Java進(jìn)程發(fā)送一個(gè)QUIT信號(hào)抒和，Java虛擬機(jī)收到信號(hào)以后就會(huì)打印出進(jìn)程的堆棧信息矫渔。一般我們會(huì)將日志信息重定向到文件中。

jstack [option] pid >> jstack.info

jstack命令使用如下：

jstack [option] pid
--參數(shù)
1. -F 強(qiáng)制打印堆棧

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

3. -l 打印額外的信息构诚，包括鎖信息

要打印堆棧日志蚌斩，首先要獲取java應(yīng)用的進(jìn)程號(hào)：

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

解讀線程堆棧

1、堆棧日志

下面是某個(gè)線程的堆棧日志：

"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)

從上面的線程堆棧信息中可以直觀的看出當(dāng)前線程的調(diào)用上下文范嘱，從哪個(gè)函數(shù)調(diào)用到哪個(gè)函數(shù)（擴(kuò)展：調(diào)用堆棧是從下往上看送膳，可以思考一下為什么？丑蛤？叠聋？）

2、線程信息

image.png

Java語言中的線程是依附于操作系統(tǒng)的線程來運(yùn)行的受裹，從本質(zhì)上來說是本地線程在執(zhí)行java線程代碼碌补，從JVM源碼角度分析，在Java中創(chuàng)建線程是棉饶，實(shí)際上創(chuàng)建一個(gè)os thread厦章，這個(gè)os才是真正的線程實(shí)體。

關(guān)于jvm虛擬機(jī)線程創(chuàng)建感興趣的可以參考該鏈接：http://www.reibang.com/p/3ce1b5e5a55e

• 線程名稱：線程創(chuàng)建的時(shí)候照藻，設(shè)置的線程名稱袜啃，建議創(chuàng)建的線程都自定義線程的名稱，通過線程名稱可以知道該線程是處理什么任務(wù)
• 守護(hù)進(jìn)程：創(chuàng)建線程的時(shí)候可以設(shè)置線程是否是守護(hù)進(jìn)程幸缕。
• 優(yōu)先級(jí)：線程創(chuàng)建的時(shí)候設(shè)置線程的優(yōu)先級(jí)群发，一般采用默認(rèn)值
• 線程id（tid）：JVM給線程分配的id號(hào)
• 本地線程id（nid）：對(duì)應(yīng)的os 線程的線程id晰韵，可以將16進(jìn)制轉(zhuǎn)換為10進(jìn)制，在os中找到對(duì)應(yīng)的線程
• 線程狀態(tài)：這線程堆棧日志中熟妓，一個(gè)線程就waiting 狀態(tài)和 runnale兩種狀態(tài)
• 線程內(nèi)存地址：線程起始地址

3雪猪、線程狀態(tài)

當(dāng)看見線程是runnable狀態(tài)時(shí)，線程不一定真正的消耗cpu起愈，出于Runnable狀態(tài)的線程只能說沒有阻塞到j(luò)ava的wait或者sleep方法上只恨，同時(shí)也沒有在進(jìn)行鎖等待，

如果該線程調(diào)用了本地方法告材，該本地方法處于等待狀態(tài)坤次，這個(gè)時(shí)候虛擬機(jī)不知道本地代碼中發(fā)生了什么，所以盡管線程已經(jīng)阻塞了斥赋，但是顯示出來的狀態(tài)還是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)    //調(diào)用本地方法的的epollWait方法产艾，此時(shí)線程阻塞疤剑，但是日志打印出來的狀態(tài)是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調(diào)用了本地方法，其實(shí)沒有在消耗cpu闷堡；只有線程正在執(zhí)行Java的指令時(shí)隘膘，才是真正的在消耗cpu。

4杠览、調(diào)用堆棧

image.png

5弯菊、鎖信息

image.png

6、鎖解讀

在java中踱阿，提供wait（）方法和sleep（）方法管钳，二者有一個(gè)共同點(diǎn)，就是阻塞當(dāng)前線程软舌，但是調(diào)用wait方法或釋放持有的鎖才漆，等待其他線程調(diào)用notify方法，才能被喚醒佛点，進(jìn)行鎖的競(jìng)爭(zhēng)醇滥。

調(diào)用sleep方法不會(huì)釋放鎖，只是讓線程讓出cpu超营。

當(dāng)一個(gè)(些)線程在等待一個(gè)鎖時(shí)鸳玩，應(yīng)該有一個(gè)線程占用這個(gè)鎖，即如果有的線程在等待一個(gè)鎖演闭，該鎖必然被另一個(gè)線程占有了不跟，也就是說，從打印的堆棧中如果能看到waiting to lock <0x22bffb60>,應(yīng)該也應(yīng)該能找到一個(gè)線程locked <0x22bffb60>

在之前的線程堆棧信息中可以看出線程的調(diào)用方法棧船响，線程的鎖信息躬拢，在日志中一般會(huì)出現(xiàn)下面三種鎖日志信息：

• 當(dāng)一個(gè)線程占有一個(gè)鎖的時(shí)候躲履，線程堆棧中會(huì)打印—locked <0x22bffb60>

• 當(dāng)一個(gè)線程正在等待其它線程釋放該鎖，線程堆棧中會(huì)打印—waiting to lock <0x22bffb60>

• 當(dāng)一個(gè)線程占有一個(gè)鎖聊闯，但又執(zhí)行到該鎖的wait()上工猜，線程堆棧中首先打印locked,然后又會(huì)打印—waiting on <0x22c03c60>

線程堆棧中與鎖相關(guān)的三個(gè)最重要的特征字:locked,waiting to lock,waiting on,了解這三個(gè)特征字，就能夠?qū)︽i進(jìn)行分析了

7菱蔬、Java線程狀態(tài)

在線程堆棧日志中篷帅，會(huì)打印java.lang.Thread.State，這個(gè)字段的狀態(tài)信息拴泌，與java里面線程狀態(tài)定義對(duì)應(yīng)

image.png

• RUNNABLE： 表示線程正在運(yùn)行魏身，在執(zhí)行本地方法的時(shí)候不一定消耗cpu

• TIMED_WAITING（parking）：表示當(dāng)前線程被掛起，調(diào)用了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)：表示當(dāng)前線程被掛起一段時(shí)間,說明該線程正在執(zhí)行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)：表示當(dāng)前線程正在被掛起一段時(shí)間蚪腐，一般是在執(zhí)行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)：當(dāng)前線程被掛起箭昵，即正在執(zhí)行obj.wait()方法(無參數(shù)的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）：表示線程真正等待一個(gè)對(duì)象鎖回季，（一般出現(xiàn)在競(jìng)爭(zhēng)公共資源的時(shí)候）如果獲得了對(duì)象鎖家制，進(jìn)入synchronized對(duì)象塊。waiting for monitor entry 說明此線程通過 synchronized(obj) {……} 申請(qǐng)進(jìn)入了臨界區(qū)泡一，從而進(jìn)入了“Entry Set”隊(duì)列颤殴，但該 obj 對(duì)應(yīng)的 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)

四、如何借助線程堆棧進(jìn)行問題分析

1鼻忠、從一次堆棧信息中涵但，我們能夠獲取到什么

• 每個(gè)線程的調(diào)用上下文
• 當(dāng)前線程正在執(zhí)行的函數(shù)
• 當(dāng)前每個(gè)線程當(dāng)前的狀態(tài)
• 當(dāng)前現(xiàn)在持有的鎖，等待的鎖帖蔓，以及鎖爭(zhēng)用信息

2矮瘟、如何定位消耗cpu最高的線程

• 獲取進(jìn)程id

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

• 獲取線程消耗cpu最多的線程
  可以通過top -Hp <pid>來看這個(gè)進(jìn)程里所有線程的cpu消耗情況

top -Hp <pid>

上面獲取到了最耗cpu的線程的id，但是是10進(jìn)制讨阻，將10進(jìn)制轉(zhuǎn)換為16進(jìn)制芥永，在導(dǎo)出的堆棧信息中找到對(duì)應(yīng)的線程，查看線程堆棧信息.

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

3钝吮、線程死鎖

image.png

4埋涧、資源不足

之前看到大量查詢現(xiàn)在被阻塞到 ibatis方法的調(diào)用中，這個(gè)時(shí)候可以分析一下是否是因?yàn)檫B接池的原因奇瘦。