[[181411]]

問題描述

當(dāng)我們一個(gè)系統(tǒng)既需要mysql驅(qū)動(dòng)，也需要oracle驅(qū)動(dòng)的時(shí)候，在并發(fā)加載初始化這些驅(qū)動(dòng)類的過程中產(chǎn)生死鎖的可能性非常大，下面是一個(gè)模擬的例子，對(duì)于Thread2的實(shí)現(xiàn)其實(shí)是jdk里java.sql.DriverService的邏輯，也是我們第一次調(diào)用java.sql.DriverManager.registerDriver注冊(cè)一個(gè)驅(qū)動(dòng)實(shí)例要走的邏輯(jdk1.6下)，不過這篇文章是使用我們生產(chǎn)環(huán)境的一個(gè)系統(tǒng)的線程dump和內(nèi)存dump為基礎(chǔ)進(jìn)行分析展開的。

如果以上代碼運(yùn)行過程中發(fā)現(xiàn)有線程一直卡死在Class.forName的調(diào)用里，那么說明問題已經(jīng)重現(xiàn)了。

先上兩張圖

內(nèi)存態(tài)線程堆棧

線程堆棧

存疑點(diǎn)

仔細(xì)看看上面的線程dump分析和內(nèi)存dump分析里的線程分析模塊，您可能會(huì)有如下兩個(gè)疑惑：

• 【為什么線程[Thread-0]一直卡在Class.forName的位置】：這有點(diǎn)出乎意料，做一個(gè)類加載要么找不到拋出ClassNotFoundException，要么找到直接返回，為什么會(huì)一直卡在這個(gè)位置呢?
• 【明明[Thread-0]注冊(cè)的是mysql驅(qū)動(dòng)為什么會(huì)去加載Odbc的驅(qū)動(dòng)類】：通過[Thread-0]在棧上看倒數(shù)第二幀展開看到傳入Class.forName的參數(shù)是com.mysql.jdbc.Driver，然后展開棧上順序第二幀，看到傳入的參數(shù)是sun.jdbc.odbc.JdbcOdbcDriver，這意味著在對(duì)mysql驅(qū)動(dòng)類做加載初始化的過程中又觸發(fā)了JdbcOdbc驅(qū)動(dòng)類的加載

疑惑點(diǎn)解釋

疑惑二：

第一個(gè)疑惑我們先留著，先解釋下第二個(gè)疑惑，大家可以對(duì)照堆棧通過反編譯rt.jar還有ojdbc6-11.2.0.3.0.jar看具體的代碼

驅(qū)動(dòng)類加載過程簡(jiǎn)要介紹:

當(dāng)要注冊(cè)某個(gè)sql驅(qū)動(dòng)的時(shí)候是通過調(diào)用java.sql.DriverManager.registerDriver來實(shí)現(xiàn)的(注意這個(gè)方法加了synchronized關(guān)鍵字，后面解釋第一個(gè)疑惑的時(shí)候是關(guān)鍵)，而這個(gè)方法在第一次執(zhí)行過程中，會(huì)在當(dāng)前線程classloader的classpath下尋找所有/META-INF/services/java.sql.Driver文件，這個(gè)文件在mysql和oracle驅(qū)動(dòng)jar里都有，里面寫的是對(duì)應(yīng)的驅(qū)動(dòng)實(shí)現(xiàn)類名，這種機(jī)制是jdk提供的spi實(shí)現(xiàn)，找到這些文件之后，依次使用Class.forName(driverClassName, true, this.loader)來對(duì)這些驅(qū)動(dòng)類進(jìn)行加載，其中第二個(gè)參數(shù)是true，意味著不僅僅做一次loadClass的動(dòng)作，還會(huì)初始化該類，即調(diào)用包含靜態(tài)塊的< clinit >方法，執(zhí)行完之后才會(huì)返回，這樣就解釋了第二個(gè)疑惑，在mysql驅(qū)動(dòng)注冊(cè)過程中還會(huì)對(duì)odbc驅(qū)動(dòng)類進(jìn)行加載并初始化

感想:

其實(shí)我覺得這種設(shè)計(jì)有點(diǎn)傻，為什么要干和自己不相關(guān)的事情呢，畫蛇添足的設(shè)計(jì)，首先類初始化的開銷是否放到一起做并沒有多大區(qū)別，其次正由于這種設(shè)計(jì)導(dǎo)致了今天這個(gè)死鎖的發(fā)生

疑惑一：

現(xiàn)在來說第一個(gè)疑惑，為什么會(huì)一直卡在Class.forName呢，到底卡在哪里，于是再通過jstack -m 命令將jvm里的堆棧也打印出來，如下所示

我們看到其實(shí)正在做類的初始化動(dòng)作，并且線程正在調(diào)用ObjectSynchronizer::waitUninterruptibly一直沒返回，在看這方法的調(diào)用者instanceKlass1::initialize_impl，我們找到源碼位置如下：

類的初始化過程:

當(dāng)某個(gè)線程獲得機(jī)會(huì)對(duì)某個(gè)類進(jìn)行初始化的時(shí)候(請(qǐng)看上面的Step 6)，會(huì)設(shè)置這個(gè)類的init_state屬性為being_initialized(如果初始化好了會(huì)設(shè)置為fully_initialized，異常的話會(huì)設(shè)置為initialization_error)，還會(huì)設(shè)置init_thread屬性為當(dāng)前線程，在這個(gè)設(shè)置過程中是有針對(duì)這個(gè)類提供了一把互斥鎖的，因此當(dāng)有別的線程進(jìn)來的時(shí)候會(huì)被攔截在外面，如果設(shè)置完了，這把互斥鎖也釋放了，但是因?yàn)檫@個(gè)類的狀態(tài)被設(shè)置了，因此并發(fā)問題也得到了解決，當(dāng)另外一個(gè)線程也嘗試初始化這個(gè)類的時(shí)候會(huì)判斷這個(gè)類的狀態(tài)是不是being_initialized，并且其init_thread不是當(dāng)前線程，那么就會(huì)一直卡在那里，也就是此次線程dump的線程所處的狀態(tài)，正在初始化類的線程會(huì)調(diào)用< clinit >方法，如果正常結(jié)束了，那么就設(shè)置其狀態(tài)為fully_initialized，并且通知之前卡在那里等待初始化完成的線程，然他們繼續(xù)往下走(下一個(gè)動(dòng)作就是再判斷下狀態(tài)，發(fā)現(xiàn)完成了就直接return了)

猜想:

在了解了上面的過程之后，于是我們猜測(cè)兩種可能

• 第一，這個(gè)類的狀態(tài)還是being_intialized，還在while循環(huán)里沒有跳出來
• 第二，事件通知機(jī)制出現(xiàn)了問題，也就是pthread_cond_wait和pthread_cond_signal之間的通信過程出現(xiàn)了問題。

不過第二種可能性非常小，比較linux久經(jīng)考驗(yàn)了，那接下來我們驗(yàn)證其實(shí)是第一個(gè)猜想

驗(yàn)證：

我們通過GDB attach的方式連到了問題機(jī)器上(好在機(jī)器沒有掛)，首先我們要找到具體的問題線程，我們通過上面的jstack -m命令看到了線程ID是5738，然后通過info threads找到對(duì)應(yīng)的線程，并得到它的序號(hào)14

然后通過thread 14切換到對(duì)應(yīng)的線程，并通過bt看到了如下的堆棧，正如我們想象的那樣，正在做類的初始化，一直卡在那里

我們通過f 6選擇第7幀，在通過disassemble反匯編該幀，也就是對(duì)instanceKlass::initialize_impl ()這個(gè)方法反匯編

從上面的注釋我們其實(shí)得出了，我們要看當(dāng)前類的初始化狀態(tài)，那就是看eax寄存器偏移0xe0的位置的值，而eax其實(shí)就是ebp寄存器偏移0xfffffff4位置的值，于是我們通過如下地址內(nèi)存查到得到是4

而4其實(shí)代表的就是being_initialized這個(gè)狀態(tài)，代碼如下

從這于是我們驗(yàn)證了第一個(gè)猜想，其實(shí)是狀態(tài)一直沒有變更，因此一直卡在那里，為了更進(jìn)一步確認(rèn)這個(gè)問題，要是我們能找到該類的init_thread線程id就更清楚了，拿到這個(gè)ID我們就能看到這個(gè)線程棧，就知道它在干什么了，但是很遺憾，這個(gè)很難獲取到，至少我一直沒有找到辦法，因?yàn)榫€程ID在線程對(duì)象里一直沒有存，都是調(diào)用的os函數(shù)來獲取的，得換個(gè)思路。

突然發(fā)現(xiàn)instanceKlass.hpp代碼中得知兩個(gè)屬性原來是相鄰的(init_state和init_thread)，于是斷定下一個(gè)地址的值就代表是這個(gè)線程對(duì)象了，但是其屬性何其多，找到想要的太不易了，最主要的是還擔(dān)心自己看的代碼和服務(wù)器上的jvm代碼不一致，這樣更蛋疼了，于是繼續(xù)查看Thread.hpp中的JavaThread類，找到個(gè)關(guān)鍵字0xDEAD-2=0xDEAB,這個(gè)有可能是volatile TerminatedTypes _terminated屬性的值，于是把線程對(duì)象打印出來，果然查到了關(guān)鍵字0xDEAB

因此順著這個(gè)屬性繼續(xù)往上找，找到了_thread_state表示線程狀態(tài)的值(向上偏移三個(gè)字)，0x0000000a，即10，然后查看代碼知道原來線程是出于block狀態(tài)

JavaThreadState

這樣一來查看下線程dump，發(fā)現(xiàn)Thread-1正好處于BLOCKED狀態(tài)，也就是說Thread-1就是那個(gè)正在對(duì)mysql驅(qū)動(dòng)類做初始化的線程，這說明Thread-0和Thread-1成功互鎖了

于是我們展開Thread-1，看到- waiting to lock <0x71ae2ec0> (a java.lang.Class for java.sql.DriverManager)，該線程正在等待java.sql.DriverManager類型鎖，而blocked在那里，而這個(gè)類型鎖是被Thread-0線程持有的，從Thread-1這個(gè)線程堆棧來看它其實(shí)也是在做Class.forName動(dòng)作，并且通過Thread-1,展開第四幀我們可以看到其正在對(duì)加載

sun.jdbc.odbc.JdbcOdbcDriver 

問題現(xiàn)場(chǎng)遐想:

于是我們大膽設(shè)想一個(gè)場(chǎng)景，Thread-1先獲取到初始化sun.jdbc.odbc.JdbcOdbcDriver的機(jī)會(huì)，然后在執(zhí)行sun.jdbc.odbc.JdbcOdbcDriver這個(gè)類的靜態(tài)塊的時(shí)候調(diào)用DriverManager.registerDriver(new Driver());，而該方法之前已經(jīng)提到了是會(huì)加同步鎖的，再想象一下，在這個(gè)這個(gè)靜態(tài)塊之前，并且設(shè)置了sun.jdbc.odbc.JdbcOdbcDriver類的初始化狀態(tài)為being_initialized之后，Thread-0這個(gè)線程執(zhí)行到了卡在的那個(gè)位置，并且我們從其堆棧可以看出它已經(jīng)持有了java.sql.DriverManager這個(gè)類型的鎖，因此這兩個(gè)線程陷入了互鎖狀態(tài)

【本文是51CTO專欄作者李嘉鵬的原創(chuàng)文章，轉(zhuǎn)載請(qǐng)通過微信公眾號(hào)(你假笨，id:lovestblog)聯(lián)系作者本人獲取授權(quán)】

戳這里，看該作者更多好文