天天看點
傳回

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

一、問題描述

在一次上線時，按照正常流程上線後，觀察了線上封包、接口可用率十分鐘以上，未出現異常情況，結果在上線一小時後突然收到jsf線程池耗盡的報警，并且該應用一共有30台機器，隻有一台機器出現該問題，迅速下線該機器的jsf接口，恢複線上。然後開始排查問題。

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

報錯日志資訊：

[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類

less複制代碼"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

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

并且此時初始化時會列印日志：

c複制代碼log.info("register: {} , clazz : {}", serializer.getCode（）, serializer.getClass（）.getName（）);

故根據此日志關鍵字排查初始化加載日志，發現正常機器都加載了兩個序列化對象，隻有出問題的那個機器隻加載了這一個序列化對象。

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

于是問題初步定位到出問題的機器初始化ProtoStuffSerializer這個類時失敗。

初始化此類時static代碼塊為：

ini複制代碼static {
    STRATEGY = new DefaultIdStrategy(IdStrategy.DEFAULT_FLAGS);
}

2）開始排查為什麼初始化這個類會失敗

由于不同機器存在初始化成功和失敗的獨立性，首先考慮jar包是否沖突

a）于是發現這裡存在jar沖突，但是将沖突jar排除後，多次重新開機機器後發現依然存在此ProtoStuffSerializer初始化失敗情況。

b）存在死鎖，但是正常邏輯下，存在死鎖的話，應該所有機器都會存在此類情況，但是此時大概隻有5%的幾率出現死鎖，并且排查jstack發現200個線程都卡在擷取ProtoStuffSerializer。

山重水盡疑無路 柳暗花明又一村

3、找到問題

此時排除了所有沒可能的選項，剩下一個可能性再低也是正确選項。

如果存在死鎖情況的話，那jstack的線程堆棧資訊肯定會報出來，于是根據jstack線程資訊逐個排查每一個線程。

最後發現下面這個線程的堆棧：

less複制代碼"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導緻的！）

于是乎開始分析此線程！

從此行棧資訊開始排查

php複制代碼at com.jd.tp.jcase.recording.agent.reporter.impl.JmqReporter$ReportRunner.run(JmqReporter.java:106)

xml中存在以下bean：

ini複制代碼<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>

發現以下代碼符合堆棧資訊：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

根據此線程的堆棧資訊逐行排查代碼，發現該線程執行JmqReporter.run方法時，會初始化RecordSerializers類；并在RecordSerializers中的靜态代碼塊會執行如下代碼：

ini複制代碼RecordSerializers.ProtostuffIdRegistry registry = new RecordSerializers.ProtostuffIdRegistry（）;

于是執行這個類的無參構造時會new出類變量：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

于是線程開始初始化ExplicitIdStrategy這個類：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

開始執行父類的有參構造：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

于是開始初始化IdStrategy類，并且執行IdStrategy類的static靜态代碼塊：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

于是此處開始初始化RuntimeEnv，并且執行RuntimeEnv的靜态代碼塊；線程堆棧資訊就顯示等待在此類了，

排查RuntimeEnv的static代碼塊時發現存在和上一個線程使用了相同的類：

arduino複制代碼new DefaultIdStrategy（）;
類加載的問題？

首次應該懷疑是類加載的問題，因為除了兩百個線程停留在加載protostuffprotostuff（初始化有new DefaultIdStrategy（）的代碼）這個類上，此線程也處于等待狀态，并且也在加載DefaultIdStrategy（）的類上。

然後再分析一下這個線程的堆棧資訊。

less複制代碼"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方法是什麼？

比如我們在類裡聲明一段static代碼塊，或者有靜态屬性，javac會将這些代碼都統一放到一個叫做clinit的方法裡，在類初始化的時候來執行這個方法，但是JVM必須要保證這個方法隻能被執行一次，如果有其他線程并發調用觸發了這個類的多次初始化，那隻能讓一個線程真正執行clinit方法，其他線程都必須等待，當clinit方法執行完之後，然後再喚醒其他等待這裡的線程繼續操作，當然不會再讓它們有機會再執行clinit方法，因為每個類都有一個狀态，這個狀态可以保證這一點。

java複制代碼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方法了

類加載的動作 

scss複制代碼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來看确實是死鎖了，那這個場景當時是怎麼發生的呢？

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

如圖所示，最後A、B線程均在等待對方初始化完成，然後C、D、E等兩百個線程需要使用ProtoStuffSerializer時，就在等待A線程初始化ProtoStuffSerializer完成。是以造成了JSF線程池爆滿。

less複制代碼"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：初始化業務所使用到的類

四、Demo驗證

Demo代碼： 

csharp複制代碼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方法");
    }
}

結果：

消失的死鎖：從 JSF 線程池滿到 JVM 初始化原理剖析 | 京東雲技術團隊

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特性也要謹慎，因為這會直接觸發接口的初始化導緻更隐蔽的循環依賴。

作者：京東物流 李鍵嶼

來源：京東雲開發者社群

原文連結：https://juejin.cn/post/7244192313844908088

技術團隊
上一篇: 近期蜂窩大闆吊頂安裝完工案例#蜂窩大闆吊頂造型效果圖
下一篇: 基于注意力機制和殘差網絡的視訊行為識别研究有何進展？ 在衆多視訊行為識别模型中，雙流法無法實作端到端的識别，利用C3D訓

繼續閱讀