开发者社区 > 博文 > 消失的死锁：从 JSF 线程池满到 JVM 初始化原理剖析
分享

  • 打开微信扫码分享

  • 点击前往QQ分享

  • 点击前往微博分享

  • 点击复制链接

消失的死锁：从 JSF 线程池满到 JVM 初始化原理剖析

  • jd****
  • 2023-06-13
  • IP归属：北京
  • 9640浏览

    一、问题描述

    在一次上线时，按照正常流程上线后，观察了线上报文、接口可用率十分钟以上，未出现异常情况，结果在上线一小时后突然收到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_END

klassOop 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


    jd****
    文章数
    1
    阅读量
    241

    作者其他文章