本例分析中所用的工具為jvisualvm（以下簡(jiǎn)稱工具），在打開(kāi)工具之前需要先啟動(dòng)fmm項(xiàng)目。本次排查問(wèn)題的方式主要是通過(guò)獲取線程快照，通過(guò)實(shí)時(shí)地查看的方法的出入棧情況，來(lái)找到問(wèn)題的出處。而項(xiàng)目在啟動(dòng)以后，隨著出棧與入棧的不斷動(dòng)態(tài)變化，每一次線程的靜態(tài)快照都是不同的，為了更快的定位到問(wèn)題的出處，我們只能在出問(wèn)題的那一時(shí)段進(jìn)行快照。換句話說(shuō)，就是在項(xiàng)目啟動(dòng)以后，我們點(diǎn)擊登錄頁(yè)面，項(xiàng)目一直處于等待狀態(tài)時(shí)，我們才能捕捉快照。

具體快照方法如圖所示

下面生成的就是某一時(shí)刻棧方法調(diào)用的情況

通過(guò)分析快照中棧方法的調(diào)用情況，很快就能發(fā)現(xiàn)有一些線程一直處于阻塞狀態(tài)。

注意那把鎖的內(nèi)存偏移量為0x0000000083a08ca8，順著這把鎖來(lái)找，很快就能找到他的出生地

根據(jù)上圖所示再結(jié)合log4j的源碼就能找到這把鎖的出生地

為了線程安全，產(chǎn)生鎖是一個(gè)再正常不過(guò)的事情，大不了再釋放它就得了。我們?cè)倮^續(xù)追蹤這個(gè)打印日志的線程，稍微有點(diǎn)眼神的人很快就會(huì)發(fā)現(xiàn)，這個(gè)打印日志的線程在還沒(méi)有釋放掉第一把鎖的時(shí)候又立馬生成了第二把鎖，如圖

而這第二把鎖就是我們要找的直接線索。這第二把鎖是個(gè)什么角色呢？聰明的觀眾肯定一眼就看到了org.apache.log4j.net.SocketAppender，看到了socket這個(gè)字眼，立馬我們就會(huì)想到它是一個(gè)網(wǎng)絡(luò)通信協(xié)議（其實(shí)順著這個(gè)線程的方法棧往上找也能證實(shí)這個(gè)結(jié)論）。有觀眾就會(huì)不解，打印日志怎么還扯上遠(yuǎn)程通信了。在此不得不為elk日志收集插播一段廣告啦。elk是一套專門(mén)收集各種日志的框架，為了提高它自身的功力，底層支持了各種數(shù)據(jù)通信協(xié)議，其中一種就包括socket。為了遠(yuǎn)程收集fmm項(xiàng)目的日志，項(xiàng)目也引進(jìn)了elk。使用方法很簡(jiǎn)單，你只需要在log4j.properties文件中進(jìn)行配置即可。

到此我們就真正追蹤到了兇手的作案現(xiàn)場(chǎng)。此時(shí)又有觀眾表示不解，為什么以前沒(méi)有發(fā)生過(guò)類似案件，而現(xiàn)在卻作案頻頻呢？帶著這個(gè)問(wèn)題，我又查看了遠(yuǎn)程服務(wù)端的elk。

一開(kāi)始我會(huì)很自然地懷疑到logstash身上，因?yàn)樗沁M(jìn)行日志收集的第一直接者。但是通過(guò)端口排查，很快這個(gè)結(jié)論被否定了。

忽然一下子又沒(méi)有了頭緒，在敲下 jps這個(gè)命令后，問(wèn)題又浮出來(lái)了。

說(shuō)好的桃園三結(jié)義！怎么只有了兩個(gè)人了，還一個(gè)kafka跑哪兒去了。此時(shí)又有人會(huì)問(wèn)。你們不是集群?jiǎn)?，走了一個(gè)不是還有另外兩個(gè)嗎？這個(gè)就只能怪當(dāng)初配置elk的作者（也就是本人）偷懶了。在搭建elk的時(shí)候，鄙人為了偷一下懶，在配置logstash與kafka的關(guān)系時(shí)，就只寫(xiě)了一個(gè)kafka與logstash發(fā)生關(guān)系，沒(méi)有寫(xiě)另外兩個(gè)（原則上三者都要寫(xiě)上）。而恰恰跑掉的那個(gè)kafka就是我配置的kafka。

到此，真正的兇手才算捉拿歸案。真兇就是遠(yuǎn)隔千里之外的，專門(mén)用來(lái)緩存日志的kafka，而它卻突然跑路了。所以不管我們?cè)趺丛趂mm的代碼層面上花力氣，都是吃力不討好！也解釋了為什么之前大家國(guó)泰民安，卻突然之間世界末日！

為了更加說(shuō)明問(wèn)題，讓我用一個(gè)大膽的比喻來(lái)縷一縷這一條線。當(dāng)項(xiàng)目啟動(dòng)以后，我們還能正常的生出一個(gè)“日志寶寶”，根據(jù)之前的劇情我們知道，當(dāng)“線程媽媽”生出這個(gè)“日志寶寶”之前，在進(jìn)入產(chǎn)房（也就是內(nèi)存中的“棧幀”）之時(shí)，“線程媽媽”手上就一直緊握著第一層產(chǎn)房門(mén)和第二層產(chǎn)房門(mén)的鑰匙，而當(dāng)“線程媽媽”生出了她的“日志寶寶”寶寶以后，當(dāng)她準(zhǔn)備要走出產(chǎn)房把兩把鑰匙交給后續(xù)的“線程媽媽”的時(shí)候，卻遲遲等不到醫(yī)生（遠(yuǎn)程logstash）給她一個(gè)明確的回復(fù)。。。孩子是死是活？？？出于“愛(ài)子心切”這個(gè)“線程媽媽”就一直呆在產(chǎn)房中焦急的等待。而更焦急的畫(huà)面是，產(chǎn)房外面卻早已排滿了其他待生產(chǎn)的“線程媽媽”！

通過(guò)上面的比喻，我們大致了解了鎖等待的原因。最終還是要回到解決問(wèn)題的層面上。找到了問(wèn)題，一切也就變的迎刃而解了。以下是幾種解決方案。

1. 關(guān)掉kafka集群重新打開(kāi)kafka

2. 注釋掉fmm項(xiàng)目中的logstash日志收集

3. 把log4j升級(jí)到2.x

4. 把日志打印的級(jí)別調(diào)到warn級(jí)別

5. 日志打印的線程改為異步形式（這種方式?jīng)]有解決根本問(wèn)題，只是緩和，因?yàn)殒i的問(wèn)題還是存在，只是被異步隱藏了，用戶感覺(jué)不到而已，隨著打印日志新線程不斷阻塞與累計(jì)，最終會(huì)擠爆線程池或還沒(méi)等線程池?cái)D爆，內(nèi)存先報(bào)了stackoverflow的錯(cuò)誤）

有人會(huì)問(wèn)，為什么項(xiàng)目啟動(dòng)的時(shí)候還能打印遠(yuǎn)遠(yuǎn)不止一條的日志呢？不是說(shuō)只打印第一條日志，后續(xù)的就處于阻塞狀態(tài)嗎？

其實(shí)我們只要仔細(xì)查看一下線程快照就會(huì)明白，產(chǎn)生鎖等待的日志打印就是在debug級(jí)別發(fā)生的，請(qǐng)看下圖。

所以，只要我們避開(kāi)debug級(jí)別的日志打印也可以避開(kāi)鎖等待（本人親測(cè)有效，可惜當(dāng)時(shí)沒(méi)有現(xiàn)場(chǎng)截圖）。但是使用warn或其他級(jí)別的日志實(shí)現(xiàn)，沒(méi)有根本解決問(wèn)題，最根本的還是升級(jí)log4j或者干脆閹割掉本項(xiàng)目的elk日志收集，或者重新連接好elk即可。雖然當(dāng)時(shí)沒(méi)有現(xiàn)場(chǎng)截圖warn級(jí)別的打印實(shí)現(xiàn)。下面卻有張圖可以旁證。

https://dzone.com/articles/log4j-thread-deadlock-case

到此，又有吃瓜的群眾表示不解了。為什么把log4j升級(jí)到2.x就能解決問(wèn)題。這個(gè)問(wèn)題，請(qǐng)觀眾自行百度腦補(bǔ)