線程堆棧信息以及解決的問題
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、線程信息
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)用堆棧
5弯菊、鎖信息
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)
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钝吮、線程死鎖
4埋涧、資源不足
之前看到大量查詢現(xiàn)在被阻塞到 ibatis方法的調(diào)用中,這個(gè)時(shí)候可以分析一下是否是因?yàn)檫B接池的原因奇瘦。