最近在做项目系统的异常测试,项目依赖于nkv,需要模拟依赖组件nkv异常时系统的响应及性能情况。通过tc工具模拟当服务器发送到nkv的请求超时时系统的响应。发现接口返回错误率100%,查看服务器日志报大量线程池已满,想要通过工具看下线程情况,由此简单学习了jstack。
WARN AbortPolicyWithReport - [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-10.165.185.170:22021, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 182763 (completed: 182563), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://10.165.185.170:22021!, dubbo version: 2.8.4-nisp, current host: 127.0.0.1
2016-11-21 13:55:33,801 WARN AbortPolicyWithReport - [DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-10.165.185.170:22021, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 182763 (completed: 182563), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://10.165.185.170:22021!, dubbo version: 2.8.4-nisp, current host: 127.0.0.1
jstack
基本介绍
jstack是用于生成java虚拟机当前时刻线程快照的工具。线程快照是当前java虚拟机内每一条线程正在执行的方法堆栈的集合,生成线程快照的主要目的是定位线程出现长时间停顿的原因,如线程间死锁、死循环、请求外部资源导致的长时间等待等。线程出现停顿的时候通过jstack来查看各个线程的调用堆栈,就可以知道没有响应的线程到底在后台做什么事情,或者等待什么资源。
命令语法格式
jstack <pid>
可以通过top查看java进程的pid
可通过jstack > jstack.log将快照打印至文件jstack.log
在实际运行中往往一次dump信息不足以确认问题,建议dump三次以便确认问题。
线程分析
线程示例
在线程中有一些JVM后台线程用于执行垃圾回收等任务,这些线程在JVM初始化时就存在,我们主要查看用户线程。在本次异常测试中,模拟异常后,系统响应慢大量报错,查看服务器日志显示线程池已满,通过jstack工具dump线程快照如下:
Full thread dump Java HotSpot(TM) 64-Bit Server VM (24.60-b09 mixed mode):
"MySQL Statement Cancellation Timer" daemon prio=10 tid=0x00000000019dc000 nid=0x3fab in Object.wait() [0x00007f035fe36000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:552)
- locked <0x00000000c45a8680> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"pool-5-thread-257" prio=10 tid=0x00000000014e7800 nid=0x3f8a waiting on condition [0x00007f035f129000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c45e9ea0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"pool-5-thread-256" prio=10 tid=0x00000000013c2800 nid=0x3f89 waiting on condition [0x00007f035f42c000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c45e9ea0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"pool-5-thread-255" prio=10 tid=0x00000000019fb000 nid=0x3f88 waiting on condition [0x00007f035f22a000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c45e9ea0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"pool-5-thread-254" prio=10 tid=0x00000000019d0000 nid=0x3f87 waiting on condition [0x00007f035f52d000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c45e9ea0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:186)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2043)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"pool-5-thread-253" prio=10 tid=0x00000000014ee000 nid=0x3f86 waiting on condition [0x00007f035f62e000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c45eabb0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"AMQP Connection 10.165.124.207:5672" prio=10 tid=0x0000000001862800 nid=0x3f85 runnable [0x00007f0360038000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:152)
at java.net.SocketInputStream.read(SocketInputStream.java:122)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
at java.io.BufferedInputStream.read(BufferedInputStream.java:254)
- locked <0x00000000c45ea970> (a java.io.BufferedInputStream)
at java.io.DataInputStream.readUnsignedByte(DataInputStream.java:288)
at com.rabbitmq.client.impl.Frame.readFrom(Frame.java:95)
at com.rabbitmq.client.impl.SocketFrameHandler.readFrame(SocketFrameHandler.java:139)
- locked <0x00000000c45ea950> (a java.io.DataInputStream)
at com.rabbitmq.client.impl.AMQConnection$MainLoop.run(AMQConnection.java:536)
at java.lang.Thread.run(Thread.java:745)
"MySQL Statement Cancellation Timer" daemon prio=10 tid=0x000000000152b800 nid=0x395a in Object.wait() [0x00007f0360139000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:503)
at java.util.TimerThread.mainLoop(Timer.java:526)
- locked <0x00000000c45f2b18> (a java.util.TaskQueue)
at java.util.TimerThread.run(Timer.java:505)
"Attach Listener" daemon prio=10 tid=0x00000000017a4000 nid=0x2168 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"pool-8-thread-1" prio=10 tid=0x00000000022e1800 nid=0x2d0 waiting on condition [0x00007f035e71f000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c05f7478> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"DubboResponseTimeoutScanTimer" daemon prio=10 tid=0x0000000002359800 nid=0x3972 waiting on condition [0x00007f035d40c000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture$RemotingInvocationTimeoutScan.run(DefaultFuture.java:300)
at java.lang.Thread.run(Thread.java:745)
"pool-7-thread-1" prio=10 tid=0x00007f036ccf4800 nid=0x3825 waiting on condition [0x00007f0360b43000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000c05f7218> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
"DubboServerHandler-10.165.185.170:22021-thread-200" daemon prio=10 tid=0x00007f036c04e000 nid=0x381b waiting on condition [0x00007f0360c43000]
java.lang.Thread.State: TIMED_WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x00000000ffcff858> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2176)
at com.netease.backend.nkv.client.rpc.net.NkvFuture.innerWait(NkvFuture.java:162)
at com.netease.backend.nkv.client.rpc.net.NkvFuture.get(NkvFuture.java:180)
at com.netease.backend.nkv.client.rpc.future.NkvResultFutureImpl.innerGet(NkvResultFutureImpl.java:144)
at com.netease.backend.nkv.client.rpc.future.NkvResultFutureImpl.get(NkvResultFutureImpl.java:81)
at com.netease.backend.nkv.client.impl.DefaultNkvClient.futureGet(DefaultNkvClient.java:530)
at com.netease.backend.nkv.client.impl.DefaultNkvClient.get(DefaultNkvClient.java:70)
at com.netease.is.ec.rpc.nkv.NkvOpService.getValue(NkvOpService.java:78)
at com.netease.is.ec.rpc.nkv.NkvOpService.setValue(NkvOpService.java:108)
at com.netease.is.ec.rpc.cacheservice.KVSqlService.setValue(KVSqlService.java:61)
at com.netease.is.ec.drag.create.CaptchaGetControl.getCaptcha(CaptchaGetControl.java:85)
at com.netease.is.ec.drag.provider.DraggingCaptchaImpl.getCaptchaImg(DraggingCaptchaImpl.java:45)
at com.alibaba.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)
at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:46)
at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:72)
at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:64)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)
at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
线程状态
Runnable
该状态表示线程具备所有运行条件,在运行队列中准备操作系统的调度,或者正在运行。