如何利用线程堆栈定位问题

1,841 阅读15分钟

01 背景

针对在一些服务中会出现的cpu飙高、死锁、线程假死等问题,总结和提炼排查问题的思路和解决方案非常重要。上述问题会涉及到线程堆栈,本文将结合实际案例来阐述一下线程堆栈的功能。

02 基本知识

2.1 什么是线程堆栈

线程堆栈是系统当时某个时刻的线程运行状态(即瞬间快照)。

线程堆栈的信息包含

  • 线程的名字、ID、线程的数量
  • 线程的运行状态、锁的状态(锁被那个线程持有,哪个线程再等待锁)
  • 调用堆栈(即函数的调用层次关系)。调用堆栈包含完整的类名,所执行的方法,源代码的行数

2.2 线程堆栈能分析问题类型

线程堆栈定位问题只能定位在当前线程上留下痕迹的问题

2.3 线程堆栈不能分析的问题

线程堆栈不能定位在线程堆栈上不留痕迹的问题:

  • 并发bug导致的数据混乱,这种问题在线程堆栈中没有任何航迹,所以这种问题线程堆栈无法提供任何帮助。
  • 数据库锁表的问题,表被锁,往往由于某个事务没有提交/回滚,但这些信息无法在堆栈中表现出现

在线程上不留痕迹的问题只能通过其他手段来进行定位。在实际的系统中,系统的问题分为几种类型:

  • 在堆栈中能够表现出问题的,使用线程堆栈进行定位
  • 无法在线程中留下痕迹的问题定位,需要依赖于一个好的日志设计
  • 非常隐蔽的问题,只能依赖于丰富的代码经验,如多线程导致的数据混乱,以及后面提到的幽灵代码

2.4 如何输出线程堆栈

kill -3 pid 命令只能打印那一瞬间java进程的堆栈信息,适合在服务器响应慢,cpu、内存快速飙升等异常情况下使用,可以方便地定位到导致异常发生的java类,解决如死锁、连接超时等原因导致的系统异常问题。该命令不会杀死进程。

备注:

将屏幕输出写入到文件中,重写文件内容

将屏幕输出添加到文件末尾

Linux常用命令

命令描述
ps查找进程的pid
pstack打印进程或者线程的栈信息
strace统计每一步系统调用花费的时间

2.5 分析线程堆栈-线程状态的分析

2.5.1 概述

2.5.2 Runnable

从虚拟机的角度来看,线程处于正在运行的状态。

那么处于RUNNABLE的线程是不是一定消耗CPU呢?实际上不一定。下面的线程堆栈表示该线程正在从网络读取数据,尽管下面这个线程显示为RUNNABLE状态,但实际上网 络IO,线程绝大多数时间是被挂起,只有当数据到达之后,线程才被重新唤醒。挂起发生在本 地代码(Native)中,虚拟机根本不知道,不像显式调用了Java的sleep()或者wait()等方法,虚拟 机能知道线程的真正状态,但对于本地代码中的挂起,虚拟机无法真正地知道线程状态,因 此它一概显示为RUNNABLE。像这种socket IO操作不会消耗大量的CPU,因为大多时间在等待,只有数据到来之后,才消耗一点点CPU.

Thread-39" daemon prio=1 tid=0x08646590 nid=0x666d runnable [5beb7000..5beb88b8]
      java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:201)
        - locked <0x47bfb940> (a java.io.BufferedInputStream)
        at org.postgresql.PG_Stream.ReceiveChar(PG_Stream.java:141)
        at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:68)
        - locked <0x47bfb758> (a org.postgresql.PG_Stream)
        at org.postgresql.Connection.ExecSQL(Connection.java:398)

下面的线程正在执行纯Java代码指令,实实在在是消耗CPU的线程。

"Thread-444" prio=1 tid=0xa4853568 nid=0x7ade runnable [0xafcf7000..0xafcf8680]
      java.lang.Thread.State: RUNNABLE
//实实在在再对应CPU运算指令
at org.apache.commons.collections.ReferenceMap.getEntry(Unknown Source) at org.apache.commons.collections.ReferenceMap.get(Unknown Source)
at org.hibernate.util.SoftLimitMRUCache.get(SoftLimitMRUCache.java:51) at org.hibernate.engine.query.QueryPlanCache.getNativeSQLQueryPlan()
at org.hibernate.impl.AbstractSessionImpl.getNativeSQLQueryPlan()
at org.hibernate.impl.AbstractSessionImpl.list()
at org.hibernate.impl.SQLQueryImpl.list(SQLQueryImpl.java:164)
at com.mogoko.struts.logic.user.LeaveMesManager.getCommentByShopId()
at com.mogoko.struts.action.shop.ShopIndexBaseInfoAction.execute() ......

下面的线程正在进行JNI本地方法调用,具体是否消耗CPU,要看TcpRecvExt的实现,如 果TcpRecvExt 是纯运算代码,那么是实实在在消耗CPU,如果TcpRecvExt()中存在挂起的代 码,那么该线程尽管显示为RUNNABLE,但实际上也是不消耗CPU的。

 "ClientReceiveThread" daemon prio=1 tid=0x99dbacf8 nid=0x7988 runnable [...]
      java.lang.Thread.State: RUNNABLE
        at com.pangu.network.icdcomm.htcpapijni.TcpRecvExt(Native Method)
        at com.pangu.network.icdcomm.IcdComm.receive(IcdComm.java:60)
        at com.msp.client.MspFactory$ClientReceiveThread.task(MspFactory.java:333)
        at com.msp.system.TaskThread.run(TaskThread.java:94)

2.5.3 TIMED_WAITING(on object monitor)

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

下面的线程堆栈表示当前线程正处于TIMED_WAITING状态,当前正在被挂起,时长为 参数中指定的时长,如obj.wait(2000)。因此该线程当前不消耗CPU。

 "JMX server" daemon prio=6 tid=0x0ad2c800 nid=0xdec in Object.wait() [...]
      java.lang.Thread.State: TIMED_WAITING (on  object  monitor)
       at java.lang.Object.wait(Native Method)
       - waiting on <0x03129da0> (a [I)
       at com.sun.jmx.remote.internal.ServerComm$Timeout.run(ServerComm.java:150)
       - locked <0x03129da0> (a [I)
       at java.lang.Thread.run(Thread.java:620)

2.5.4 TIMED_WAITING(sleeping)

表示当前线程被挂起一段时间,即正在执行Thread.sleep(int time)方法.

下面的线程正处于TIMED_WAITING状态,表示当前被挂起一段时间,时长为参数中指 定的时长,如Thread.sleep(100000)。因此该线程当前不消耗CPU。

 "Comm thread" daemon prio=10 tid=0x00002aaad4107400 nid=0x649f waiting on condition
    [0x000000004133b000..0x000000004133ba00]
       java.lang.Thread.State: TIMED_WAITING (sleeping)
            at java.lang.Thread.sleep(Native Method)
            at org.apache.hadoop.mapred.Task$1.run(Task.java:282)
            at java.lang.Thread.run(Thread.java:619)

2.5.5 TIMED_WAITING(parking)

当前线程被挂起一段时间,即正在执行Thread.sleep(int time)方 法.

下面的线程正处于TIMED_WAITING状态,表示当前被挂起一段时间,时长为参数中指 定的时长,如LockSupport.parkNanos(blocker, l10000) 。因此该线程当前不消耗CPU。

"RMI TCP" daemon prio=6 tid=0x0ae3b800 nid=0x958 waiting on condition [0x17eff000..0x17effa94]
 java.lang.Thread.State: TIMED_WAITING (parking)
       at sun.misc.Unsafe.park(Native Method)
       - parking to wait for  <0x02f49f58> (a java.util.concurrent.SynchronousQueue$TransferStack)
       at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:179)
       at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:424)
       at java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:323)
       at java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:871)
       at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:495)
       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:693)
       at java.lang.Thread.run(Thread.java:620)

2.5.6 WAINTING(on object monitor)

当前线程被挂起,即正在执行obj.wait()方法(无参数的wait()方 法).

下面的线程正处于WAITING状态,表示当前线程被挂起,如obj.wait()(只能通过notify()唤 醒)。因此该线程当前不消耗CPU。

 "IPC Client" daemon prio=10 tid=0x00002aaad4129800 nid=0x649d in Object.wait() [0x039000..0x039d00]
       java.lang.Thread.State: WAITING (on object monitor)
            at java.lang.Object.wait(Native Method)
            - waiting on <0x00002aaab3acad18>; (aorg.apache.hadoop.ipc.Client$Connection)
            at java.lang.Object.wait(Object.java:485)
            at org.apache.hadoop.ipc.Client$Connection.waitForWork(Client.java:234)
            - locked <0x00002aaab3acad18> (aorg.apache.hadoop.ipc.Client$Connection)
            at org.apache.hadoop.ipc.Client$Connection.run(Client.java:273)

2.5.7 总结

处于TIMED_WAITING、WAITING状态的线程一定不消耗CPU,处于Runable的线程,要结合当前线程代码的性质判断,是否消耗CPU。

  • 如果纯java运算代码,则消耗CPU

  • 如果是网络IO,很少消耗CPU

  • 如果是本地代码,结合本地代码的性质判断(可以通过pstack/gstack获取本地线程堆栈),如果是纯运算代码,则消耗CPU,如果被挂起,则不消耗CPU,如果是IO,则不怎么消耗CPU。

03 CPU飙高

3.1 概述

系统的CPU的飙高的原因有很多,下面罗列一下一些常见的场景:

3.2 死循环导致CPU飙高

死循环并不一定会导致CPU的100%利用率,如果死循环中的代码不是CPU密集型,而是像Socket或者数据库IO操作,这些操作是不怎么消耗CPU的。但如果循环代码中是CPU密集型操作,那这就是导致CPU利用率100%的可能原因。

定位问题的方法是:通过多次打印线程堆栈

主要流程如下:

  1. 获取第一次堆栈信息
  2. 等待一定的时间,再获取第二次堆栈信息。
  1. 预处理两次堆栈信息,首先去掉处于sleeping或者waiting状态的线程,因为这种线程是不消耗CPU的
  2. 比较第一次堆栈和第二次堆栈预处理后的线程,找出这段时间一直活跃的线程,如果两次堆栈中同一个线程处于同样的调用上下文,那么就应该列为重点怀疑对象。具体情况需要结合代码详细分析。导致这种情况的可能原因猜测是:

猜测一:检查该线程的执行上下所对应的代码是否属于长期运行的代码。

猜测二:如果不属于长期运行的代码,那么这个线程为什么长期执行不完那段代码,可能的原因是代码出现死循环了。

导致死循环出现的原因:

  • 多线程:for,while循环中的退出条件永远不满足导致的死循环。
  • 多线程:链表等数据结构首尾相接,导致遍历永远无法停止
  • 其问题

3.3 非死循环导致CPU飙高

导致CPU飙高的可能原因:

  • 虚拟机自身的代码导致的CPU过高,比如GC的bug等

定位问题的方法是:通过打印线程堆栈

主要流程如下:

第一步:获取目标进程id(pid),使用命令可以获取进程ID,jps -l 或 ps -ef |grep java

第二步:通过top -Hp pid 获取该进程下最消耗CPU的本地线程ID。

第三步:打印线程堆栈,使用如下命令,jstack -l pid

第四步:将十进制的本地线程ID换算成16进制,采用如下命令:printf "0x%x\n" 53841(本地线程ID), 输出Oxd251。

第五步:在java线程堆栈中查找nid=<第一步获取的最耗CPU时间的线程ID(十进制换算成的十六进制的本地线程ID)>,具体分析如下

  • 如果在java线程堆栈中找到了对应的线程ID,并且该线程正在执行纯java代码,说明是该java代码导致的CPU过高的。
  • 如果在java线程堆栈中找到了对应的线程ID,并且该线程正在执行native code代码,说明是导致的CPU过高的问题代码在JNI调用中。
  • 如果在java线程堆栈中找不到了对应的线程ID,有如下两种可能:
    • JNI调用中重新创建的线程来执行,那么在java线程堆栈中就不存在该线程的信息。
    • 虚拟机自身代码导致的CPU过高,如堆内存枯竭导致的频繁Full GC,或者虚拟机bug等
    • 此时同样可以通过pstack pid命令获取所有的本地线程堆栈,根据之前获取的最耗时CPU时间的线程ID,在本地线程堆栈中找到对应的线程,即为高消耗CPU的线程。借助本地线程堆栈信息,可以直接定位到本地代码找出问题。

04 系统假死

4.1 概述

系统假死只是一个表面现象。系统假死,从表面上看,是系统不处理响应。对于web系统来说,http请求无数据返回。总之来说,系统像死了一样。导致系统假死的原因很多,具体的问题需要在特定的场景下进行分析,但总的归结原因有如下几种:

备注:特殊情况,系统假死,当一个服务即对外提供http和rpc服务时,两者使用的不同的线程池,即使其中一个线程池中的线程产生死锁,另外一个线程池仍然可以提供服务

4.2 线程死锁

4.2.1 死锁和定位方法

什么死锁

当两个线程或多个线程正在等待被对方占有的锁,死锁就会发生。死锁会导致两个线程无法继续运行,被永远挂起。

定位问题的方法是:打印线程堆栈。如出现死锁时,在打印线程堆栈时虚拟机会自动给出死锁的提示。

4.2.2 背景

在2021.12.13 11:15 refund-interfaces 服务上这台机器10.240.49.153 操作命令挂载沙箱,在11:32:19分在流量回放平台操作录制,此时返回操作失败,对录制失败进行问题排查,在11:34 分,order服务有接口报服务超时,但是从refund-interface 监控上看,这台10.240.49.153的监控不存在,其他都是正常的,11:59才发现这台机器仍然在dubbo的注册中心,当时情况没有比较好手段保存现场,只能将机器重启,破会了现场。事后初步猜测是在高并发的情况下,操作平台的录制功能导致发生死锁。而发生死锁时,要想恢复系统,临时也是唯一规避的办法就是将系统重启。

为保证服务的可用性,在发生异常情况下,降级方案和问题排查思路

通常的降级方案是:

【方案一】保存现场法-摘除流量法,目前我司该方案并不完善

1.对于http,需要从网关摘除流量,即是consul

2.对于rpc,需要从dubbo的注册中心摘除流量,即是nacos

3.对于mq,服务接入MQ的消费端摘除流量

【方案二】万能法-机器重启

通常的问题排查思路是:尽量保存现场,便于事后问题排查!!!!

备注:对于死锁的发生,如没有保留现场,需要对其发现的手段是通过压测的方式。因为代码如有发生死锁的潜在可能并不意味照死锁每次都发生,它只发生该发生的时候,当死锁出现的时候,往往是遇到了最不幸的时候-在高负载的生产环境之下

4.2.3 通过压测方式来复现死锁

4.2.3.1 现象

在2021-12-27 11:58:15没有监控,压测是存在,服务进程是存在的,在12:02 dump线程堆栈进行观察,如上

4.2.3.2 dump 线程堆栈

Found one Java-level deadlock:
=============================
"DubboServerHandler-10.246.144.236:20888-thread-200":
  waiting to lock monitor 0x00007faa6c00c128 (object 0x00000006bd2a0000, a com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader),
  which is held by "com.alibaba.nacos.client.naming.updater"
"com.alibaba.nacos.client.naming.updater":
  waiting to lock monitor 0x00007fa91c0568b8 (object 0x00000006bcf0de00, a com.alibaba.jvm.sandbox.core.classloader.ModuleJarClassLoader),
  which is held by "XNIO-1 task-44"
"XNIO-1 task-44":
  waiting to lock monitor 0x00007fa904004848 (object 0x0000000722c10c48, a java.lang.Object),
  which is held by "com.alibaba.nacos.client.naming.updater"

Java stack information for the threads listed above:
===================================================
"DubboServerHandler-10.246.144.236:20888-thread-200":
	at com.pandora.jvm.sandbox.repeater.plugin.dubbo.DubboProviderInvocationProcessor.assembleIdentity(DubboProviderInvocationProcessor.java:39)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.api.DefaultEventListener.sample(DefaultEventListener.java:194)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.api.DefaultEventListener.onEvent(DefaultEventListener.java:89)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleEvent(EventListenerHandler.java:117)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnBefore(EventListenerHandler.java:353)
	at java.com.alibaba.jvm.sandbox.spy.Spy.spyMethodOnBefore(Spy.java:164)
	at org.apache.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java)
	at org.apache.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:81)
	at org.apache.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:147)
	at org.apache.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:81)
	at org.apache.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)
	at org.apache.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:81)
	at org.apache.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:41)
	at org.apache.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:81)
	at org.apache.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:145)
	at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:100)
	at org.apache.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:175)
	at org.apache.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51)
	at org.apache.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:57)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:51)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:55)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:775)
"com.alibaba.nacos.client.naming.updater":
	at java.lang.ClassLoader.checkCerts(ClassLoader.java:881)
	- waiting to lock <0x00000006bcf0de00> (a com.alibaba.jvm.sandbox.core.classloader.ModuleJarClassLoader)
	at java.lang.ClassLoader.preDefineClass(ClassLoader.java:662)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:755)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:468)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:74)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:369)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.access$400(RoutingURLClassLoader.java:22)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader$1.loadClass(RoutingURLClassLoader.java:91)
	at com.alibaba.jvm.sandbox.core.classloader.ClassLoadingLock.loadingInLock(ClassLoadingLock.java:55)
	- locked <0x0000000722c10c48> (a java.lang.Object)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.loadClass(RoutingURLClassLoader.java:64)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:406)
	- locked <0x00000006bd2a0000> (a com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader)
	at com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader.loadClass(PluginClassLoader.java:47)
	- locked <0x00000006bd2a0000> (a com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at com.pandora.jvm.sandbox.repeater.plugin.exception.ExceptionEventListener.sample(ExceptionEventListener.java:34)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.api.DefaultEventListener.onEvent(DefaultEventListener.java:89)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleEvent(EventListenerHandler.java:117)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnBefore(EventListenerHandler.java:353)
	at java.com.alibaba.jvm.sandbox.spy.Spy.spyMethodOnBefore(Spy.java:164)
	at java.lang.RuntimeException.<init>(RuntimeException.java:62)
	at java.lang.IllegalArgumentException.<init>(IllegalArgumentException.java:52)
	at java.lang.NumberFormatException.<init>(NumberFormatException.java:55)
	at java.lang.Long.parseLong(Long.java:552)
	at java.lang.Long.parseLong(Long.java:631)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1845)
	- locked <0x0000000722cc9928> (a sun.net.www.protocol.http.HttpURLConnection)
	at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1498)
	- locked <0x0000000722cc9928> (a sun.net.www.protocol.http.HttpURLConnection)
	at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
	at com.alibaba.nacos.common.http.client.response.JdkHttpClientResponse.getStatusCode(JdkHttpClientResponse.java:75)
	at com.alibaba.nacos.common.http.client.handler.AbstractResponseHandler.handle(AbstractResponseHandler.java:43)
	at com.alibaba.nacos.common.http.client.NacosRestTemplate.execute(NacosRestTemplate.java:483)
	at com.alibaba.nacos.common.http.client.NacosRestTemplate.exchangeForm(NacosRestTemplate.java:427)
	at com.alibaba.nacos.client.naming.net.NamingProxy.callServer(NamingProxy.java:599)
	at com.alibaba.nacos.client.naming.net.NamingProxy.reqApi(NamingProxy.java:524)
	at com.alibaba.nacos.client.naming.net.NamingProxy.reqApi(NamingProxy.java:491)
	at com.alibaba.nacos.client.naming.net.NamingProxy.reqApi(NamingProxy.java:486)
	at com.alibaba.nacos.client.naming.net.NamingProxy.queryList(NamingProxy.java:400)
	at com.alibaba.nacos.client.naming.core.HostReactor.updateService(HostReactor.java:339)
	at com.alibaba.nacos.client.naming.core.HostReactor$UpdateTask.run(HostReactor.java:420)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:51)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:55)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:775)
"XNIO-1 task-44":
	at com.alibaba.jvm.sandbox.core.classloader.ClassLoadingLock.loadingInLock(ClassLoadingLock.java:53)
	- waiting to lock <0x0000000722c10c48> (a java.lang.Object)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.loadClass(RoutingURLClassLoader.java:64)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.dewuext.TraceExtension.dewuTrace(TraceExtension.java:51)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.api.DefaultEventListener.onEvent(DefaultEventListener.java:76)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleEvent(EventListenerHandler.java:117)
	at com.alibaba.jvm.sandbox.core.enhance.weaver.EventListenerHandler.handleOnBefore(EventListenerHandler.java:353)
	at java.com.alibaba.jvm.sandbox.spy.Spy.spyMethodOnBefore(Spy.java:164)
	at io.jaegertracing.internal.JaegerSpan.finish(JaegerSpan.java)
	at com.poizon.fusion.monitor.instrument.jdbc.MonitorPreparedStatement.execute(MonitorPreparedStatement.java:97)
	at io.shardingsphere.shardingjdbc.jdbc.core.statement.MasterSlavePreparedStatement$3.executeSQL(MasterSlavePreparedStatement.java:152)
	at io.shardingsphere.shardingjdbc.jdbc.core.statement.MasterSlavePreparedStatement$3.executeSQL(MasterSlavePreparedStatement.java:149)
	at io.shardingsphere.spi.executor.MasterSlaveSQLExecuteCallback.execute0(MasterSlaveSQLExecuteCallback.java:17)
	at io.shardingsphere.shardingjdbc.jdbc.core.statement.MasterSlavePreparedStatement.execute(MasterSlavePreparedStatement.java:155)
	at com.poizon.fusion.monitor.instrument.jdbc.MonitorPreparedStatement.execute(MonitorPreparedStatement.java:89)
	at org.apache.ibatis.executor.statement.PreparedStatementHandler.query(PreparedStatementHandler.java:64)
	at org.apache.ibatis.executor.statement.RoutingStatementHandler.query(RoutingStatementHandler.java:79)
	at org.apache.ibatis.executor.SimpleExecutor.doQuery(SimpleExecutor.java:63)
	at org.apache.ibatis.executor.BaseExecutor.queryFromDatabase(BaseExecutor.java:324)
	at org.apache.ibatis.executor.BaseExecutor.query(BaseExecutor.java:156)
	at org.apache.ibatis.executor.CachingExecutor.query(CachingExecutor.java:109)
	at com.github.pagehelper.PageInterceptor.intercept(PageInterceptor.java:108)
	at org.apache.ibatis.plugin.Plugin.invoke(Plugin.java:61)
	at com.sun.proxy.$Proxy419.query(Unknown Source)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:147)
	at org.apache.ibatis.session.defaults.DefaultSqlSession.selectList(DefaultSqlSession.java:140)
	at sun.reflect.GeneratedMethodAccessor490.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.mybatis.spring.SqlSessionTemplate$SqlSessionInterceptor.invoke(SqlSessionTemplate.java:426)
	at com.sun.proxy.$Proxy192.selectList(Unknown Source)
	at org.mybatis.spring.SqlSessionTemplate.selectList(SqlSessionTemplate.java:223)
	at org.apache.ibatis.binding.MapperMethod.executeForMany(MapperMethod.java:147)
	at org.apache.ibatis.binding.MapperMethod.execute(MapperMethod.java:80)
	at org.apache.ibatis.binding.MapperProxy.invoke(MapperProxy.java:93)
	at com.sun.proxy.$Proxy193.selectByExample(Unknown Source)
	at com.shizhuang.duapp.refund.infrastructure.db.dao.RefundOrderDao.getReturnBySubOrderNoList(RefundOrderDao.java:1049)
	at com.shizhuang.duapp.refund.infrastructure.db.dao.RefundOrderDao$$FastClassBySpringCGLIB$$41f7ca21.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:56)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
	at com.shizhuang.duapp.refund.infrastructure.db.dao.RefundOrderDao$$EnhancerBySpringCGLIB$$28f9b058.getReturnBySubOrderNoList(<generated>)
	at com.shizhuang.duapp.refund.application.service.refund.app.impl.QueryRefundDetailInBuyerOrderDetailService.hasRefund(QueryRefundDetailInBuyerOrderDetailService.java:147)
	at com.shizhuang.duapp.refund.interfaces.facade.refund.app.RefundOrderDesc2OldOrderDetailController.hasRefund(RefundOrderDesc2OldOrderDetailController.java:150)
	at com.shizhuang.duapp.refund.interfaces.facade.refund.app.RefundOrderDesc2OldOrderDetailController$$FastClassBySpringCGLIB$$da692b9e.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:88)
	at com.poizon.fusion.monitor.instrument.openfeign.aspect.FeignClientAspect.invoke(FeignClientAspect.java:109)
	at sun.reflect.GeneratedMethodAccessor486.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:175)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
	at com.shizhuang.duapp.refund.interfaces.facade.refund.app.RefundOrderDesc2OldOrderDetailController$$EnhancerBySpringCGLIB$$25d2f6d1.hasRefund(<generated>)
	at sun.reflect.GeneratedMethodAccessor497.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:665)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
	at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
	at com.shizhuang.duapp.dubbo.environment.ServletEnvironmentFilter.doFilter(ServletEnvironmentFilter.java:28)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at com.alibaba.druid.support.http.WebStatFilter.doFilter(WebStatFilter.java:124)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at com.shizhuang.duapp.sentinel.client.servlet.SentinelServletFilter.doFilter(SentinelServletFilter.java:90)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at com.poizon.fusion.webmvc.logging.AccessLoggingFilter.doFilterInternal(AccessLoggingFilter.java:63)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114)
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at com.poizon.fusion.monitor.instrument.spring.web.server.servlet.MonitorServletFilter.doFilter(MonitorServletFilter.java:170)
	at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
	at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
	at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
	at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
	at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
	at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
	at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
	at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:132)
	at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
	at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
	at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
	at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
	at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
	at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:269)
	at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:78)
	at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:133)
	at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:130)
	at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
	at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
	at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:249)
	at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:78)
	at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:99)
	at io.undertow.server.Connectors.executeRootHandler(Connectors.java:376)
	at io.uXNIO-1 task-44":
	at com.alibaba.jvm.sandbox.core.classloader.ClassLoadingLock.loadingInLock(ClassLoadingLock.java:53)
	- waiting to lock <0x0000000722c10c48> (a java.lang.Object)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.loadClass(RoutingURLClassLoader.java:64)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.dewuext.TraceExtension.dewuTrace(TraceExtension.java:51)ndertow.server.HttpServerExchange$1.run(HttpServerExchange.java:830)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:51)
	at com.alibaba.ttl.TtlRunnable.run(TtlRunnable.java:55)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:775)

Found 1 deadlock.

备注:

有一些令人头疼的死锁场景,比如类加载过程发生的死锁,尤其是在框架大量使用自定义类加载时,因为往往不是在应用本身的代码库中, jstack等工具也不见得能够显示全部锁信息。

4.2.3.3 dump文件分析

线程XNIO-1

XNIO-1 task-44":
	at com.alibaba.jvm.sandbox.core.classloader.ClassLoadingLock.loadingInLock(ClassLoadingLock.java:53)
	- waiting to lock <0x0000000722c10c48> (a java.lang.Object)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.loadClass(RoutingURLClassLoader.java:64)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at com.pandora.jvm.sandbox.repeater.plugin.core.impl.dewuext.TraceExtension.dewuTrace(TraceExtension.java:51)

线程com.alibaba.nacos.client.naming.updater

"com.alibaba.nacos.client.naming.updater":
	at java.lang.ClassLoader.checkCerts(ClassLoader.java:881)
	- waiting to lock <0x00000006bcf0de00> (a com.alibaba.jvm.sandbox.core.classloader.ModuleJarClassLoader)
	at java.lang.ClassLoader.preDefineClass(ClassLoader.java:662)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:755)
	at java.security.SecureClassLoader.defineClass(SecureClassLoader.java:142)
	at java.net.URLClassLoader.defineClass(URLClassLoader.java:468)
	at java.net.URLClassLoader.access$100(URLClassLoader.java:74)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:369)
	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.access$400(RoutingURLClassLoader.java:22)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader$1.loadClass(RoutingURLClassLoader.java:91)
	at com.alibaba.jvm.sandbox.core.classloader.ClassLoadingLock.loadingInLock(ClassLoadingLock.java:55)
	- locked <0x0000000722c10c48> (a java.lang.Object)
	at com.alibaba.jvm.sandbox.core.classloader.RoutingURLClassLoader.loadClass(RoutingURLClassLoader.java:64)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:406)
	- locked <0x00000006bd2a0000> (a com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader)
	at com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader.loadClass(PluginClassLoader.java:47)
	- locked <0x00000006bd2a0000> (a com.pandora.jvm.sandbox.repeater.module.classloader.PluginClassLoader)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:352)
	at com.pandora.jvm.sandbox.repeater.plugin.exception.ExceptionEventListener.sample(ExceptionEventListener.java:34)

结合代码分析

线程XNIO-1

线程com.alibaba.nacos.client.naming.updater

4.2.3.4 结论

在高并发情况,类加载加锁导致死锁的

4.2.3.5 解决方案

提前加载RepeatCache和Tracer类

4.3 线程假死

线程假死是线程一直处于运行中,不退出。

定位问题的方法是:打印线程堆栈

业务中需要使用spark进行数据处理,因此将spark任务上传到服务器执行,但是main 线程一直hang住。通过打印线程堆栈,摘出其中的部分线程堆栈,如下:

"main" #1 prio=5 os_prio=0 tid=0x00007f0d98009800 nid=0x6240b runnable [0x00007f0d9ec49000]
   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:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at com.mysql.cj.protocol.ReadAheadInputStream.fill(ReadAheadInputStream.java:107)
	at com.mysql.cj.protocol.ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(ReadAheadInputStream.java:150)
	at com.mysql.cj.protocol.ReadAheadInputStream.read(ReadAheadInputStream.java:180)
	- locked <0x000000072028a7b8> (a com.mysql.cj.protocol.ReadAheadInputStream)
	at java.io.FilterInputStream.read(FilterInputStream.java:133)
	at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeaderLocal(SimplePacketReader.java:81)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
	at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
	at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:514)
	at com.mysql.cj.protocol.a.NativeProtocol.readServerCapabilities(NativeProtocol.java:475)
	at com.mysql.cj.protocol.a.NativeProtocol.beforeHandshake(NativeProtocol.java:362)
	at com.mysql.cj.protocol.a.NativeProtocol.connect(NativeProtocol.java:1367)
	at com.mysql.cj.NativeSession.connect(NativeSession.java:133)
	at com.mysql.cj.jdbc.ConnectionImpl.connectWithRetries(ConnectionImpl.java:842)
	at com.mysql.cj.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:823)
	- locked <0x0000000722c7fc40> (a com.mysql.cj.jdbc.ConnectionImpl)
	at com.mysql.cj.jdbc.ConnectionImpl.<init>(ConnectionImpl.java:448)
	at com.mysql.cj.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:241)
	at com.mysql.cj.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:198)
	at org.apache.spark.sql.execution.datasources.jdbc.connection.BasicConnectionProvider.getConnection(BasicConnectionProvider.scala:49)
	at org.apache.spark.sql.execution.datasources.jdbc.connection.ConnectionProvider$.create(ConnectionProvider.scala:68)
	- locked <0x0000000722c7fe18> (a org.apache.spark.security.SecurityConfigurationLock$)
	at org.apache.spark.sql.execution.datasources.jdbc.JdbcUtils$.$anonfun$createConnectionFactory$1(JdbcUtils.scala:62)
	at org.apache.spark.sql.execution.datasources.jdbc.JdbcUtils$$$Lambda$1606/936828380.apply(Unknown Source)
	at org.apache.spark.sql.execution.datasources.jdbc.JdbcRelationProvider.createRelation(JdbcRelationProvider.scala:48)
	at org.apache.spark.sql.execution.datasources.SaveIntoDataSourceCommand.run(SaveIntoDataSourceCommand.scala:46)
	at org.apache.spark.sql.execution.command.ExecutedCommandExec.sideEffectResult$lzycompute(commands.scala:70)
	- locked <0x0000000722c96c18> (a org.apache.spark.sql.execution.command.ExecutedCommandExec)
	at org.apache.spark.sql.execution.command.ExecutedCommandExec.sideEffectResult(commands.scala:68)
	at org.apache.spark.sql.execution.command.ExecutedCommandExec.doExecute(commands.scala:90)
	at org.apache.spark.sql.execution.SparkPlan.$anonfun$execute$1(SparkPlan.scala:180)
	at org.apache.spark.sql.execution.SparkPlan$$Lambda$1492/203829039.apply(Unknown Source)
	at org.apache.spark.sql.execution.SparkPlan.$anonfun$executeQuery$1(SparkPlan.scala:218)
	at org.apache.spark.sql.execution.SparkPlan$$Lambda$1516/376234567.apply(Unknown Source)
	at org.apache.spark.rdd.RDDOperationScope$.withScope(RDDOperationScope.scala:151)
	at org.apache.spark.sql.execution.SparkPlan.executeQuery(SparkPlan.scala:215)
	at org.apache.spark.sql.execution.SparkPlan.execute(SparkPlan.scala:176)
	at org.apache.spark.sql.execution.QueryExecution.toRdd$lzycompute(QueryExecution.scala:132)
	- locked <0x0000000722ca3c78> (a org.apache.spark.sql.execution.QueryExecution)
	at org.apache.spark.sql.execution.QueryExecution.toRdd(QueryExecution.scala:131)
	at org.apache.spark.sql.DataFrameWriter.$anonfun$runCommand$1(DataFrameWriter.scala:989)
	at org.apache.spark.sql.DataFrameWriter$$Lambda$1379/456240898.apply(Unknown Source)
	at org.apache.spark.sql.execution.SQLExecution$.$anonfun$withNewExecutionId$5(SQLExecution.scala:103)
	at org.apache.spark.sql.execution.SQLExecution$$$Lambda$1387/862090614.apply(Unknown Source)
	at org.apache.spark.sql.execution.SQLExecution$.withSQLConfPropagated(SQLExecution.scala:163)
	at org.apache.spark.sql.execution.SQLExecution$.$anonfun$withNewExecutionId$1(SQLExecution.scala:90)
	at org.apache.spark.sql.execution.SQLExecution$$$Lambda$1380/1008095885.apply(Unknown Source)
	at org.apache.spark.sql.SparkSession.withActive(SparkSession.scala:775)
	at org.apache.spark.sql.execution.SQLExecution$.withNewExecutionId(SQLExecution.scala:64)
	at org.apache.spark.sql.DataFrameWriter.runCommand(DataFrameWriter.scala:989)
	at org.apache.spark.sql.DataFrameWriter.saveToV1Source(DataFrameWriter.scala:438)
	at org.apache.spark.sql.DataFrameWriter.saveInternal(DataFrameWriter.scala:415)
	at org.apache.spark.sql.DataFrameWriter.save(DataFrameWriter.scala:301)
	at org.apache.spark.sql.DataFrameWriter.jdbc(DataFrameWriter.scala:817)
	at com.pandora.spark.task.job.EsSparkSqlRecordDataHandle.main(EsSparkSqlRecordDataHandle.java:111)

   Locked ownable synchronizers:
	- None

通过对上面的堆栈分析可以发现main线程的状态为:RUNNABLE,且阻塞在方法

ReadAheadInputStream.fill(ReadAheadInputStream.java:107),通过查看配置发现没有配置相关connectTimeout和socketTimeout等参数,通过配置上面超时参数之后,就出现其它的报错。

05 系统运行越来越慢

5.1 概述

系统缓慢一般是由于如下几个原因造成的:

  1. 堆内存泄漏造成的内存不足,导致系统越来越慢,直到停止。
  2. Xmx设置太小造成的堆内存不足,导致系统越来越慢,直到停止。
  1. 系统出现死循环,消耗了过多的CPU。参考上一节的内容
  2. 资源不足导致性系统运行越来越慢。

\

5.2 内存泄漏

5.2.1 定位方式

判断系统是否存在内存泄漏的依据是:如果系统存在内存泄漏,那么在完成垃圾回收之后的内存值应该持续上升。如果在现场能观察到这个现象,说明系统存在内存泄漏。 当怀疑 一个系统存在内存泄漏的时候,首先使用FULL GC信息对内存泄漏进行一个初步确认,确认系统是否存在内存泄漏。只检查完全垃圾回收后的可用内存值是否一直再增大,步骤如下:

  • 首先截取系统稳定运行以后的GC信息(如初始化已经完成),这个非常重要,非稳定运行 期的信息无分析价值,因为你无法确认内存的增长是正常的增长还是由于内存泄漏导致 的非正常增长。
  • 过滤出FULL GC的行。只有FULL GC的行才有分析价值。因为完成GC后的内存是当前Java对象真正使用的内存数量。一般系统会有两种可能:
    • 如果完成垃圾回收后的内存持续增长,大有一直增长到Xmx设定值的趋势,那么这 个时候基本上就可以断定系统存在内存泄漏。
    • 如果当前完成垃圾回收后内存增长到一个值之后,又能回落,总体上处于一个动态 平衡,那么内存泄漏基本可以排除。

通过如上内存使用趋势分析之后,基本上就能确定系统是否存在堆内存泄漏。当然这 种GC信息分析只能告诉你系统是否存在堆内存泄漏,但具体哪里泄漏,它是无法告诉你的。 内存泄漏的的精确定位,是要找到内存泄漏的具体位置,需要通过dump内存堆栈,通过其内存堆栈分析工具才能找到真正导致内存泄漏的类或者对象。

5.2.2 案例

jvm 监控:

内存堆栈分析:

通过内存堆栈,定位到如下代码

原因猜测:

1.通过jvm的内存监控上看,这个泄漏几天,而且泄漏的速度是一条直线(近似匀速),如果是业务调用导致内存泄漏应该会有起伏,猜测可能是定时任务调用dubbo的逻辑。

验证

5.3 资源不足

5.3.1 特点和定位方法

特点:如资源不足,那么会存在大量的线程在等待资源,打印的线程堆栈如果具有这个特征,那么就说明该系统资源是瓶颈。对于资源不足导致性能下降,打印出的线程堆栈中会存在大量的线程停在同样的调用上下文中。

资源不足或者资源使用不恰当,表现出来往往是一个性能问题。系统越来越慢,并最终停止响应。遇到系统变慢等问题,定位问题的方法是打印线程堆栈。

5.3.2 可能的原因

5.3.3 案例

备注:当时没有对服务打印线程堆栈。

从监控上看,数据库的连接池已经打满(连接池当时配置的60)。从客户端角度来看,当时客户端单机的cpu、memory都没有使用满,从服务端(mysql)来看,db没有任何异常。因此可以看出瓶颈卡在数据库连接上。

从具体的业务场景来分析,该问题有两种解决方案:

方案一:资源隔离法。因为从该业务上看,只有流量上报和回放上报的接口的qps高,而平台的其他接口qps低,并且都是平台后台的基本操作的方法。将流量上报和回放上报使用一个数据库连接池,平台的其他接口使用另外一个连接池。

方案二:提高数据库的连接池,该方式有点缺点是会影响后台的页面操作, 出现页面卡顿的情况。

06 性能分析

6.1 概述

线程堆栈进行性能分析使用场景:多线程场合下的性能瓶颈定位。特别是锁的使用不当,导致的性能瓶颈。

改善性能意味着用更少的资源做更多的事。当线程的运行因某个特定资源受阻时,称之为受限该资源:受限数据库、受限对端的处理能力。

性能调优的终极目标是系统的CPU利用率接近100%。如果系统的CPU没有被充分利用,那么可能存在如下问题:施加的压力不足,可能被测试的系统没有被加入到足够的压力(负载),这时候可以通过增加压力,检测系统的响应时间、服务失败率和CPU使用率情况。如果增加压力,系统开始出现部分服务失败,系统的响应时间变慢,或者CPU的使用率无法再上升,那么此时的压力应该是系统的饱和压力。即此时的能力是系统当前的最大能力。

系统存在瓶颈:当系统在饱和压力下,如果CPU的使用率没有接近100%,那么说明这个系统性能的还有提升的空间。如果系统存在如下问题,那么可以使用线程堆栈查找性能瓶颈的方法进行问题定位。

  • 持续运行缓慢。时常发现应用程序运行缓慢。通过改变环境因子(如数据库连接数等)也无法有效提升整体响应时间
  • 系统性能随时间的增加逐渐下降。在负载稳定的情况下,系统运行时间越长速度越慢。可能是由于超出某个阈值范围,系统运行频繁出错从而导致系统死锁或崩溃。
  • 系统性能随负载的增加逐渐下降。随着用户数目的增多,应用程序的运行越发缓慢。若干用户退出系统,应用程序便能够恢复正常运行状态。

6.2 常见的性能瓶颈

  • 由于不恰当的同步导致的资源争用
    • 不相关的两个函数,共用了一个锁或者不同的共享变量共用了一个锁,无谓地制造出了资源争用
    • 锁的粒度过大,对共享资源访问完成之后,没有将后续的代码放在synchronized同步代码块之外。
  • sleep 的滥用:sleep只适合用在等待固定时长的场合,如果轮询代码中夹杂着sleep()调用,这 种设计必然是一种糟糕的设计。这种设计在某些场合下会导致严重的性能瓶颈。

  • String + 滥用

  • 不恰当的线程模型: 在多线程场合下,如果线程模型不恰当,也会使性能低下。

  • 效率低下的SQL语句或者不恰当的数据库设计

  • 线程数量不足:在使用线程池的场合,如果线程池的线程配置太少,也会导致性能低下。

  • 内存泄漏导致的频繁GC:内存泄漏会导致GC越来越频繁,而GC操作是CPU密集型操作,频 繁GC会导致系统整体性能严重下降。

6.3 压测发现性能瓶

性能瓶颈的特征

  • 当前的性能瓶颈只有一处,只有当解决的这一块,才知道下一处。没有解决当前的性能瓶颈,下一处性能瓶颈是不会出现的
  • 性能瓶颈是动态的,低负载下不是瓶颈的地方,在高负载下可能成为瓶颈。

6.4 如何通过线程堆栈识别性能瓶颈

一个系统一旦出现性能瓶颈,从堆栈上分析,有如下三种最为典型的堆栈特征:

  1. 绝大多数线程的堆栈都表现为在同一个调用上下文上,且只剩下非常少的空闲线程。可能的原因如下:
  • 线程的数量过少
  • 锁的粒度过大导致的锁竞争。
  • 资源竞争(如数据库连接池中连接不足,导致有些企图获取连接的线程被阻塞)
  • 锁范围内有大量耗时操作(如大量的磁盘IO),导致锁争用。
  • 远程通信的对方处理缓慢(甚至导致socket缓冲区写满),如数据库侧的SQL代码性能 低下。
  1. 绝大多数线程处于等待状态,只有几个工作的线程,总体性能上不去。可能的原因是,系 统存在关键路径,在该关键路径上没有足够的能力给下个阶段输送大量的任务,导致其 它地方空闲。如在消息分发系统,消息分发一般是一个线程,而消息处理是多个线程,这 时候消息分发是瓶颈的话,那么从线程堆栈就会观察到上面提到的现象:即该关键路径 没有足够的能力给下个阶段输送大量的任务,导致其它地方空闲。

  2. 线程总的数量很少。导致性能瓶颈的原因与上面的类似。这里线程很少,是由于某些线 程池实现使用另一种设计思路,当任务来了之后才new出线程来,这种实现方式下,线程 的数量上不去,就意味有在某处关键路径上没有足够的能力给下个阶段输送大量的任务, 从而不需要更多的线程来处理。

6.5 线程堆栈进行性能分析总结

07 总结

本文是在阅读《java问题定位技术》等相关书籍和文档,结合发生在生产环境下的真实案例下进行梳理和总结,一方面提升问题排查能力,同时也对其进行总结和提炼,另外一方面希望通过总结和提炼本文能够帮助到大家提升问题排查能力和对线程堆栈的充分认识。

08 参考资料

《java问题定位技术》

文/小宝

关注得物技术,做最潮技术人