博客 / 詳情

返回

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

一、問題描述

在一次上線時，按照正常流程上線後，觀察了線上報文、接口可用率十分鐘以上，未出現異常情況，結果在上線一小時後突然收到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

作者：京東物流 李鍵嶼

來源：京東雲開發者社區

線程池 , jvm , 鎖 , jsf
user avatar juanerma 頭像 godbmw 頭像
2 位用戶收藏了這個故事！

發佈 評論

Some HTML is okay.