消失的死鎖：從 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"  init-method="start" destroy-method="stop">
    <constructor-arg name="name" value="https://www.cnblogs.com/Jcloud/p/jmq"/>
    <constructor-arg name="recorder" ref="jcaseRecorder"/>
    <constructor-arg name="topic" value="https://www.cnblogs.com/Jcloud/p/${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方法是什么？

比如我們在類里宣告一段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 = https://www.cnblogs.com/Jcloud/p/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：初始化業務所使用到的類

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方法");
    }
}

標籤：Java

上一篇：驅動開發：內核ShellCode執行緒注入

下一篇：返回列表