关于锁:消失的死锁从-JSF-线程池满到-JVM-初始化原理剖析-京东云技术团队

49次阅读

共计 10361 个字符，预计需要花费 26 分钟才能阅读完成。

一、问题形容

在一次上线时，依照失常流程上线后，察看了线上报文、接口可用率十分钟以上，未出现异常状况，后果在上线一小时后忽然收到 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

作者：京东物流 李键屿

起源：京东云开发者社区

正文完
锁
发表至： 锁
2023-06-14
 0
关于锁:java锁机制
关于锁:消失的死锁从-JSF-线程池满到-JVM-初始化原理剖析-京东云技术团队
关于锁:Java常见锁
关于锁:第38问分区表到底要上多少锁