一、问题形容

在一次上线时,依照失常流程上线后,察看了线上报文、接口可用率十分钟以上,未出现异常状况,后果在上线一小时后忽然收到jsf线程池耗尽的报警,并且该利用一共有30台机器,只有一台机器呈现该问题,迅速下线该机器的jsf接口,复原线上。而后开始排查问题。

报错日志信息:

[WARN]2023-04-10 18:03:34.847 [ - ][] |[JSF-23002]Task:java.util.concurrent.FutureTask@502cdfa0 has been reject for ThreadPool exhausted! pool:200, active:200, queue:0, taskcnt: 2159[BusinessPool#:][JSF-SEV-WORKER-225-T-8]

二、问题剖析

1、呈现问题起因:

a)因为只有一台机器呈现线程池耗尽,其余机器均失常运行。所以第一工夫判断是否为有大量流量负载不平衡导致;

b)业务代码存在并发锁;

c)业务代码解决工夫较长;

d)拜访数据源(如DB、redis)变慢;

排查接口流量UMP监控,依照机器纬度看,发现每个机器流量是平衡的,排除a)项;

排查业务量大的接口UMP KEY监控,依照机器纬度看,失常机器和异样机器耗时基本一致,并于平常统一,无较大差别,排除c)项;

排查数据库监控,无慢sql,读写均无耗时较长的状况,排除d)项;

综上,只剩下b)项,确认问题起因是代码存在并发锁,故开始排查日志及业务代码。

2、依据已确认的起因排查思路:

1)down下dump文件,发现极多JSF线程处于RUNNABLE状态,并且堆栈处于SerializersHelper类

"JSF-BZ-22000-223-T-200" #1251 daemon prio=5 os_prio=0 tid=0x00007fd15005c000 nid=0xef6 in Object.wait() [0x00007fce287ac000]   java.lang.Thread.State: RUNNABLE    at com.jd.purchase.utils.serializer.helper.SerializersHelper.ofString(SerializersHelper.java:79)    at com.jd.ldop.pipe.proxy.OrderMiddlewareCBDExportServiceProxy.getAddress(OrderMiddlewareCBDExportServiceProxy.java:97)    at com.jd.ldop.pipe.proxy.OrderMiddlewareCBDExportServiceProxy.findOrder(OrderMiddlewareCBDExportServiceProxy.java:211)

依据堆栈信息排查代码,发现代码会初始化一个自定义的序列化工厂类:SerializerFactory

并且此时初始化时会打印日志:

log.info("register: {} , clazz : {}", serializer.getCode(), serializer.getClass().getName());

故依据此日志关键字排查初始化加载日志,发现失常机器都加载了两个序列化对象,只有出问题的那个机器只加载了这一个序列化对象。

于是问题初步定位到出问题的机器初始化ProtoStuffSerializer这个类时失败。

初始化此类时static代码块为:

static {    STRATEGY = new DefaultIdStrategy(IdStrategy.DEFAULT_FLAGS);}

2)开始排查为什么初始化这个类会失败

因为不同机器存在初始化胜利和失败的独立性,首先思考jar包是否抵触

a)于是发现这里存在jar抵触,然而将抵触jar排除后,屡次重启机器后发现仍然存在此ProtoStuffSerializer初始化失败状况。

b)存在死锁,然而失常逻辑下,存在死锁的话,应该所有机器都会存在此类情况,然而此时大略只有5%的几率呈现死锁,并且排查jstack发现200个线程都卡在获取ProtoStuffSerializer。

山重水尽疑无路 柳暗花明又一村

3、找到问题

此时排除了所有没可能的选项,剩下一个可能性再低也是正确选项。

如果存在死锁状况的话,那jstack的线程堆栈信息必定会报进去,于是依据jstack线程信息一一排查每一个线程。

最初发现上面这个线程的堆栈:

"jcase-jmq-reporter-t-0" #1010 daemon prio=5 os_prio=0 tid=0x00007fd258004800 nid=0x9ba in Object.wait() [0x00007fd10fffd000]   java.lang.Thread.State: RUNNABLE    at io.protostuff.runtime.RuntimeEnv.<clinit>(RuntimeEnv.java:229)    at io.protostuff.runtime.IdStrategy.<clinit>(IdStrategy.java:53)    at io.protostuff.runtime.ExplicitIdStrategy$Registry.<init>(ExplicitIdStrategy.java:67)    at com.jd.tp.jcase.util.RecordSerializers$ProtostuffIdRegistry.<init>(RecordSerializers.java:108)    at com.jd.tp.jcase.util.RecordSerializers.<clinit>(RecordSerializers.java:34)    at com.jd.tp.jcase.recording.agent.reporter.impl.JmqReporter$ReportRunner.run(JmqReporter.java:106)    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:748)

发现此线程(in Object.wait())也仍然处于期待状态,并且此线程的堆栈信息中蕴含了protostuff这个关键字(因为下面线程都期待在初始化protostuffprotostuff导致的!)

于是乎开始剖析此线程!

从此行栈信息开始排查

at com.jd.tp.jcase.recording.agent.reporter.impl.JmqReporter$ReportRunner.run(JmqReporter.java:106)

xml中存在以下bean:

<bean id="jcaseJmqReporter" class="com.jd.tp.jcase.recording.agent.reporter.impl.JmqReporter" init-method="start" destroy-method="stop">    <constructor-arg name="name" value="jmq"/>    <constructor-arg name="recorder" ref="jcaseRecorder"/>    <constructor-arg name="topic" value="${jmq.topic.ldopjcasereporter}"/>    <constructor-arg name="producer" ref="jcaseJmqProducer"/>    <property name="config" ref="jcaseConfig"/></bean>

发现以下代码合乎堆栈信息:

依据此线程的堆栈信息逐行排查代码,发现该线程执行JmqReporter.run办法时,会初始化RecordSerializers类;并在RecordSerializers中的动态代码块会执行如下代码:

RecordSerializers.ProtostuffIdRegistry registry = new RecordSerializers.ProtostuffIdRegistry();

于是执行这个类的无参结构时会new出类变量:

于是线程开始初始化ExplicitIdStrategy这个类:

开始执行父类的有参结构:

于是开始初始化IdStrategy类,并且执行IdStrategy类的static动态代码块:

于是此处开始初始化RuntimeEnv,并且执行RuntimeEnv的动态代码块;线程堆栈信息就显示期待在此类了,

排查RuntimeEnv的static代码块时发现存在和上一个线程应用了雷同的类:

new DefaultIdStrategy();
类加载的问题?

首次应该狐疑是类加载的问题,因为除了两百个线程停留在加载protostuffprotostuff(初始化有new DefaultIdStrategy()的代码)这个类上,此线程也处于期待状态,并且也在加载DefaultIdStrategy()的类上。

而后再剖析一下这个线程的堆栈信息。

"jcase-jmq-reporter-t-0" #1010 daemon prio=5 os_prio=0 tid=0x00007fd258004800 nid=0x9ba in Object.wait() [0x00007fd10fffd000]   java.lang.Thread.State: RUNNABLE    at io.protostuff.runtime.RuntimeEnv.<clinit>(RuntimeEnv.java:229)    at io.protostuff.runtime.IdStrategy.<clinit>(IdStrategy.java:53)    at io.protostuff.runtime.ExplicitIdStrategy$Registry.<init>(ExplicitIdStrategy.java:67)    at com.jd.tp.jcase.util.RecordSerializers$ProtostuffIdRegistry.<init>(RecordSerializers.java:108)    at com.jd.tp.jcase.util.RecordSerializers.<clinit>(RecordSerializers.java:34)    at com.jd.tp.jcase.recording.agent.reporter.impl.JmqReporter$ReportRunner.run(JmqReporter.java:106)    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:748)   Locked ownable synchronizers:    - <0x00000000c81fce28> (a java.util.concurrent.ThreadPoolExecutor$Worker)

能够看到在RuntimeEnv、IdStrategy后都有<clinit>;

从名字上来不难猜到是正在做类的初始化,那咱们先来理解下类的初始化过程。

类的初始化过程

当咱们第一次被动调用某个类的静态方法就会触发这个类的初始化,当然还有其余的触发状况,类的初始化说白了就是在类加载起来之后,在某个适合的机会执行这个类的clinit办法。

clinit办法是什么?

比方咱们在类里申明一段static代码块,或者有动态属性,javac会将这些代码都对立放到一个叫做clinit的办法里,在类初始化的时候来执行这个办法,然而JVM必须要保障这个办法只能被执行一次,如果有其余线程并发调用触发了这个类的屡次初始化,那只能让一个线程真正执行clinit办法,其余线程都必须期待,当clinit办法执行完之后,而后再唤醒其余期待这里的线程持续操作,当然不会再让它们有机会再执行clinit办法,因为每个类都有一个状态,这个状态能够保障这一点。

public static class ClassState {    public static final InstanceKlass.ClassState ALLOCATED = new InstanceKlass.ClassState("allocated");    public static final InstanceKlass.ClassState LOADED = new InstanceKlass.ClassState("loaded");    public static final InstanceKlass.ClassState LINKED = new InstanceKlass.ClassState("linked");    public static final InstanceKlass.ClassState BEING_INITIALIZED = new InstanceKlass.ClassState("beingInitialized");    public static final InstanceKlass.ClassState FULLY_INITIALIZED = new InstanceKlass.ClassState("fullyInitialized");    public static final InstanceKlass.ClassState INITIALIZATION_ERROR = new InstanceKlass.ClassState("initializationError");    private String value;    private ClassState(String value) {        this.value = value;    }    public String toString() {        return this.value;    }}

当有个线程正在执行这个类的clinit办法的时候,就会设置这个类的状态为being\_initialized,当失常执行完之后就马上设置为fully\_initialized,而后才唤醒其余也在等着对其做初始化的线程持续往下走,在持续走上来之前,会先判断这个类的状态,如果曾经是fully_initialized了阐明有线程曾经执行完了clinit办法,因而不会再执行clinit办法了

类加载的动作

void TemplateTable::checkcast() {   ...   call_VM(rax, CAST_FROM_FN_PTR(address, InterpreterRuntime::quicken_io_cc));   ...}IRT_ENTRY(void, InterpreterRuntime::quicken_io_cc(JavaThread* thread)) // Force resolving; quicken the bytecode int which = get_index_u2(thread, Bytecodes::_checkcast); constantPoolOop cpool = method(thread)->constants(); // We'd expect to assert that we're only here to quicken bytecodes, but in a multithreaded // program we might have seen an unquick'd bytecode in the interpreter but have another // thread quicken the bytecode before we get here. // assert( cpool->tag_at(which).is_unresolved_klass(), "should only come here to quicken bytecodes" ); klassOop klass = cpool->klass_at(which, CHECK); thread->set_vm_result(klass);IRT_ENDklassOop klass_at(int which, TRAPS) {   constantPoolHandle h_this(THREAD, this);   return klass_at_impl(h_this, which, CHECK_NULL);}klassOop constantPoolOopDesc::klass_at_impl(constantPoolHandle this_oop, int which, TRAPS) {   ...   klassOop k_oop = SystemDictionary::resolve_or_fail(name, loader, h_prot, true, THREAD);   ...}    //SystemDictionary::resolve_or_fail最终会调用到上面这个办法klassOop SystemDictionary::resolve_instance_class_or_null(Symbol* name, Handle class_loader, Handle protection_domain, TRAPS) { ... // Class is not in SystemDictionary so we have to do loading. // Make sure we are synchronized on the class loader before we proceed Handle lockObject = compute_loader_lock_object(class_loader, THREAD); check_loader_lock_contention(lockObject, THREAD); ObjectLocker ol(lockObject, THREAD, DoObjectLock); ... //此时会调用ClassLoader.loadClass来加载类了 ...}Handle SystemDictionary::compute_loader_lock_object(Handle class_loader, TRAPS) { // If class_loader is NULL we synchronize on _system_loader_lock_obj if (class_loader.is_null()) {   return Handle(THREAD, _system_loader_lock_obj); } else {   return class_loader; }}

SystemDictionary::resolve\_instance\_class\_or\_null这个办法十分要害了,在外面咱们看到会获取一把锁ObjectLocker,其相当于咱们java代码里的synchronized关键字,而对象对应的是lockObject,这个对象是下面的SystemDictionary::compute\_loader\_lock_object办法返回的,从代码可知只有不是bootstrapClassloader加载的类就会返回以后classloader对象,也就是说当咱们在加载一个类的时候其实是会持有以后类加载对象的锁的,在获取了这把锁之后就会调用ClassLoader.loadClass来加载类了。

小结

看到这里是否能解释了咱们线上为什么会有那么多线程会卡在某一个中央了?因为这个类的状态是being_initialized,所以只能等了。

这个类加载的锁,不过遗憾的是因为这把锁不是java层面来显示加载的,因而咱们在jstack线程dump的输入里竟然看不到这把锁的存在。

从dump来看的确是死锁了,那这个场景过后是怎么产生的呢?

如图所示,最初A、B线程均在期待对方初始化实现,而后C、D、E等两百个线程须要应用ProtoStuffSerializer时,就在期待A线程初始化ProtoStuffSerializer实现。因而造成了JSF线程池爆满。

"JSF-BZ-22000-223-T-1" #980 daemon prio=5 os_prio=0 tid=0x00007fd164002000 nid=0x99a in Object.wait() [0x00007fd1de8b7000]   java.lang.Thread.State: RUNNABLE    at com.jd.purchase.utils.serializer.impl.ProtoStuffSerializer.<clinit>(ProtoStuffSerializer.java:42)    at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)    at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)    at java.lang.reflect.Constructor.newInstance(Constructor.java:423)

只有此线程获取到了ProtoStuffSerializer的初始化锁也间接证实了这一点。

三、解决方案

理解到是因为A、B线程相互抢夺对方的初始化锁后,那么为了突破这一点,就让其中某一个线程提前初始化这些类就能够了。

这里抉择提前加载这个bean:初始化业务所应用到的类

<bean class="com.jd.purchase.utils.serializer.starter.CustomSerializerStarter"/>

四、Demo验证

Demo代码:

public class JVMTest {    public static void main(String[] args) {        new Thread(){            public void run(){                B.test();            }        }.start();        new Thread(){            public void run(){                A.test();            }        }.start();    }}class A{    static{        int a=0;        System.out.println(a);        B.test();    }    static void test(){        System.out.println("调用了A的test办法");    }}class B{    static{        int b=0;        System.out.println(b);        A.test();    }    static void test(){        System.out.println("调用了B的test办法");    }}

后果:

Demo景象解释

咱们Demo里的那两个线程,从dump来看的确是死锁了,那这个场景过后是怎么产生的呢?

线程1首先执行B.test(),于是会对B类做初始化,设置B的类状态为being_initialized,接着去执行B的clinit办法,然而在clinit办法里要去调用A.test办法,实践上此时会对A做初始化并调用其test办法,然而就在设置完B的类状态之后,执行其clinit里的A.test办法之前;

线程2却执行了A.test办法,此时线程2会优先负责对A的初始化工作,即设置A类的状态为being\_initialized,而后再去执行A的clinit办法,此时线程1发现A的类状态是being\_initialized了,那线程1就认为有线程对A类正在做初始化,于是就期待了,而线程2同样发现B的类状态也是being_initialized,于是也开始期待,这样就造成了两个线程都在期待另一个线程实现初始化的状况,造成了类死锁的景象。

五、总结

类加载的死锁很荫蔽了,然而类初始化的死锁更荫蔽,所以大家要谨记在类的初始化代码里产生循环依赖,另外对于jdk8的defalut个性也要审慎,因为这会间接触发接口的初始化导致更荫蔽的循环依赖。

举荐浏览:

JDK的sql设计不合理导致的驱动类初始化死锁问题:https://blog.csdn.net/xichenguan/article/details/39578401

java虚拟机标准—初始化:https://blog.csdn.net/weixin_38233104/article/details/125251345

JVM常用命令:https://zhuanlan.zhihu.com/p/401563061

作者:京东物流 李键屿

起源:京东云开发者社区