雜談---令人抓狂的數據庫行級鎖問題


引言

 

  本篇文章只是工作當中的一個簡單記錄,盡管這次遇到的問題從技術上來講並不算是特別高深的問題,但是在面臨着多方壓力的情況下,問題的解決還是有着不小的難度。因此這里LZ就簡單的描述一下整個問題從出現到解決所采取的一系列措施,如果有對此經驗豐富的猿友,不妨指點一二。倘若是新手猿友,尚未遇到過此類問題,也算是一個小小的引導吧。

 

東窗事發

 

  9月27號的一天中午,LZ正在悠閑的聽着音樂,exception happy的寫着增刪改查的代碼。忽然之間,狂風大作,通訊工具瘋狂彈窗,打破了LZ的閑情逸致。消息當中顯示,某業務部門在頃刻之間,整個華北地區的營業部的業務無法進行。在問題出現后的半個小時之內,問題已然延伸到整個部門全國的營業部業務都無法進行。這簡直是十分可怕的問題,LZ可擔待不起。

  當時問題的根源就發生在LZ所負責的系統當中,而很巧的是,我們的項目經理剛好請假了,於是這一重任就落在了LZ的肩上。不過LZ所負責的系統類似於一個窗口,其實在這之后,還有很多項目組在幕后默默的提供着服務,當然,也可能在默默的制造着錯誤。當時LZ在受到反饋之后,就立馬找到運維組同事查看后台日志,結果發現出現了大量的“unable to create new native thread”。

  好在LZ對JVM的運行機制以及參數配置還比較熟悉,一看到這個錯誤,LZ就斷定,問題基本上只有兩個可能。第一個是,Xss參數太大,導致每個線程的棧太大,從而減少了整體可創建的線程數量。第二個可能是,有大批量的線程一直在進行,但卻一直不終止,最終導致線程數量過大。

  對於這兩個可能,LZ很干脆的就排除掉了第一個,因為我們的系統運行了三年之多,怎么可能將JVM的參數配置錯誤。所以問題的根源,一定是有一些線程,一直在運行,類似於while(true)的情況。可是很顯然,系統當中不可能出現這么多while(true)的線程,那么這些線程究竟為何一直在運行呢?

  正在LZ一籌莫展的時候,DBA組的同事給了一個十分有用的線索,DBA組的同事發現,我們系統的數據庫當中,出現了大量的行級鎖,而且這些鎖的數量還在不斷增加,導致數據庫連接數巨大,壓力劇增幾近崩潰。由於數據庫的服務器上不只運行着一個數據庫實例,所以DBA組的同事強烈要求LZ停止系統運行。

  這一下信息量有點大,LZ一時也很難快速定位問題的所在,因此只能妥協,暫停了整個系統的運行。在問題出現的前一天晚上,LZ的系統剛剛上線了一大批功能。此時在業務部門的極力催促之下,LZ在短時間內也無法找到問題根源,盡管不甘,但迫於各方面的壓力,LZ最終只能采取了回退策略。而且在案發現場,公司的CTO已經到場,因為LZ系統給數據庫造成的壓力已經影響到了很多系統。

  在回退之后,系統終於恢復了正常,從出問題到恢復,共歷時一個半小時。不過這也等於失去了排錯的機會,只能留着一些比較模糊的信息,私底下自己排查。這些模糊的信息主要包括以下幾點。

  1、代碼回退之后,問題解決,因此可能是代碼的問題。

  2、數據庫產生行級鎖,因此與事務有關。

  3、線程數量劇增,說明有線程被長時間掛起。

  之后LZ私底下也進行了排查,經查之后,代碼沒有發現任何問題,但第一條的情況卻表明,很可能是代碼所造成的問題。出現問題的一段代碼,只是一個普通的service層的方法,這類方法在系統中大批量存在,LZ實在看不出來哪里有問題。之后在LZ的系統再次上線時,也並未再出現上一次所出現的問題,因此這個問題有點不了了之的意思了。【后話:其實現在這樣一分析,從上面三點已經可以找出一些蛛絲馬跡了。只是LZ在當時當局者迷,加上俗務纏身,所以才忽略了這個重要的線索】

 

纏人夢魘

  

  10月31日,今天本來是特別悠閑的一天,盡管LZ手中有着不少開發任務,但時間還算是比較寬裕,因此也算是不慌不忙。然而事情往往會發生在你預料之外,就在LZ剛吃完午飯,享受着人生最美好的時刻的時候(飯后一支煙,你懂的),卻被一個小小的噩耗猛然間打斷。而噩耗的根源,正是上一次不了了之的那個問題,如今已經時隔一個多月,這充分說明了,“出來混,遲早是要還的”。

  當LZ從冒煙處回到工位上時,已然收到無數同事的批判,大體上的意思都是說,LZ的系統中一個依賴於MQ的接口再次出現了問題(與上次出現的問題的地方是一樣的),導致業務流程無法進行,業務部門已經炸鍋。LZ的通訊軟件一根煙的功夫就彈出來N(N>=10)個窗口,郵箱也幾近爆滿。批判的同事更是來自四面八方,有運維組的,有業務部門的,有研發部門的,有DBA組的,全部都在問同樣一個問題,“你們系統怎么回事?現在所有XX部門(某業務部門,由於業務辦理周期很短,所以有什么問題都比較火急火燎)都無法正常開展業務了!”。

 

冷靜對待

 

  經過了上次的陣仗,LZ這一次更加蛋定了,輕咳一聲,開始挨個仔細的詢問各個組(不包括業務部門)的同事一個問題,“有什么異常情況嗎?”。對於業務部門,LZ只能采取安撫策略,於是只好扔過去一句“放心,問題應該不大,請稍等一下,我看看是怎么回事!”。接下來LZ收到的,便是技術部各個組同事的一系列反饋,以及來自業務部門的錯誤截圖和描述。

  業務人員的反饋:在點某個按鈕的時候(此按鈕背后是由MQ包裝的接口,業務人員自然是不知道的,他們只知道是這個按鈕造成的問題),網頁似乎一直在提交(就是無限讀進度條),也不提示錯誤,但是也不提示成功,導致業務流程無法進行,后果嚴重。

  運維組的反饋:后台會有異常信息出現,顯示為“無返回結果”。(收到此反饋后,嘗試了一下,LZ發現並不是對請求沒有響應,而是時間很長,最終會產生無返回結果的異常)

  開發人員的反饋:這里的開發人員是我們出問題的這個接口的服務端開發人員,他們表示系統無異常信息。

  DBA組的反饋:數據庫有行級鎖,而且數量一直在堆積,導致數據庫隨時面臨被壓垮的危險。(這個表現與上次一模一樣)

  這次之所以可以蛋定的收集信息,是因為項目經理在壓陣,否則就LZ一個人,身份低微,扛不住業務部門以及技術部各個組的壓力,只能像之前那次一樣,放棄治療,先讓系統恢復再說。而這一次有項目經理抗着就不一樣了,LZ可以隨時再現問題,這樣就可以更好的定位問題了。

  

隨機應變

 

  由於數據庫的行級鎖問題,導致數據庫壓力太大,隨時面臨崩潰的可能,而且數據庫的服務器上並不只有一個數據庫,這還可能導致其它業務系統的崩潰。因此數據庫的問題是當下之急,為此DBA組特意派專員及時幫我們殺掉產生的行級鎖,釋放數據庫的session連接,避免了數據庫服務器壓力驟增而宕機的問題(上次導致好幾個系統的數據庫全部崩潰)。

  抗着業務部門以及技術部各個組同事的壓力,LZ與另外一個項目組A組(也就是出問題的接口的服務端,以下都簡稱A組)的核心開發以及項目經理,開始排查問題出現的可能性。從數據庫的表現上來看,問題基本已經斷定在接口這個service層的方法當中,而出現問題的應該是方法當中的事務沒有及時的提交或回滾,接下來便是一系列排查問題的過程。

  

日志查詢

 

  日志的作用不需要多說,LZ先從服務器上down下來了發生問題的時間段的日志,開始一一檢查當中出現的異常。結果卻令人十分不滿意,因為日志當中並沒有什么可用的信息,唯一的一類異常,還是我們自己拋出來的(如下),而且業務人員的反饋是頁面長時間沒有響應,並不是系統報錯(事實證明,業務人員的話一般是不可信的,不是因為他們說謊,而是因為他們的世界與我們是不一樣的)。

    if(result == null){ throw new RuntimeException(); }

  上面這個異常是因為MQ監聽消息通道時,接收的結果為空所拋出的,當時寫這一段代碼的開發人員的目的,應該是希望通過unchecked異常使得事務管理器將事務回滾。但是可惜的是,事務很顯然沒有正常回滾,也沒有正常提交。

 

代碼審查

 

  日志查詢並沒有發現什么有用的信息,因為程序的顯示是正常的,雖然拋出了運行時異常,但這屬於事務失敗而回滾的正常情況。接下來,我們就只能排查出問題的service層的方法,不過從spring事務管理器的使用慣例上來看,這一段代碼並沒有任何問題,只是簡單的update、insert以及消息發送。

  在看代碼的時候我們不能忘了一點,那就是這個問題是忽然出現的,如果代碼的邏輯或者事務管理是有問題的,那么在測試的時候,或者上一次上線的時候,就應該出現問題。事實上,這一段代碼已經很久沒有更改,並成功運行了很久(代碼的極度縮減版如下所示)。

    public class XXXService{ private XXXDao XXXdao; public void methodWithAProblem(){ XXXDao.update();
       
       sendMessage();
     }
}

  在此次出問題的方法當中,代碼的量其實並不大,因此代碼審查的時間並沒有使用太多。不過可惜的是,代碼的審查與日志的查詢一樣,都沒有取得實質性的效果,因此LZ就不得不拿出了必殺技。

 

瘋狂的日志

 

  既然代碼看上去沒有明顯的事務管理問題,而且事實上這段代碼也成功運行了很久,因此在代碼審查上花費再長時間,也很難定位問題。LZ當機立斷,只能采取最卑劣的做法,將這個方法當中,任何一個有關數據庫操作的后面都加入日志,並打印詳細的參數信息,可以說是一句代碼一句日志。

  之后LZ便聯系運維組的同事,將修改后並編譯好的class文件放到服務器上去,並采取了重啟的措施。重啟其實是挺有壓力的,因為很多業務人員在用,畢竟此次出問題的,只是系統中某一個規模相對中等部門的業務,其它大部分的業務還是可以正常進行的。

  不過既然冒險重啟了,收獲就必定是可觀的。在系統重啟之后,LZ便再次詳細查看了本次打印的日志,終於找到了一些蛛絲馬跡,問題很可能出現在消息中間件上面了。但是此時還依舊不能夠定性問題的根源,因為日志只是將問題縮小到了很小的范圍,但具體系統與消息中間件的傳輸過程以及消息中間件與接口服務端的傳輸過程都還是不太明確的。

  況且,令人糾結的是,就算與消息中間件的通信出現了問題,那也應該可以獲得一個unchecked異常,從而導致事務回滾,而不是產生行級鎖。而且行級鎖的出現,一定是有很多人在修改一條數據,這從業務上來講是不可能出現的,因為這些數據都是業務人員的業績,有嚴格的權限控制,彼此之間都是互斥的。

 

水落石出

 

  最終LZ從時間上發現了問題,從等待A組系統返回消息開始,到LZ的系統得到“無返回結果”(無返回結果的原因是消息的響應為null,而LZ也專門看了API的說明,上面的return項很清晰的寫着null if time out)的異常為止,時間剛好是30秒,而LZ發現我們的MQ設置的超時時間恰好是30秒。這絕對不是一種巧合,因此LZ此時已經基本斷定,是服務端(也就是A組系統)沒有及時響應產生的問題。

  在LZ跟項目經理說了原因之后,項目經理還問了LZ一句,“既然是超時引起的,為何會有行級鎖?難道業務人員會操作一條數據?”。LZ腦子一轉,忽然想到一種可能,就是業務人員很可能在等待時寂寞難耐,從而F5刷新之后再次點擊,這樣一來,由於上一個請求還在等待,並且將事務掛起,接下來的請求就需要等待行級鎖,如果多次進行這種操作,那么最終掛起來的線程將會越多越多。如果有很多業務人員如此操作,產生的行級鎖也將會越來越多。這是LZ能想到的唯一可以完美解釋一切的原因。

  這樣一分析,上次的“unable to create new native thread”異常也就可以解釋了。因為很多請求由於行級鎖被掛起,這些線程都在等待數據庫的行級鎖,因此堆積了大量的線程,導致線程數巨大,最終無法再創建。

 

后續花絮

 

  問題既然已經找到,那么接下來就是LZ找到A組項目經理以及開發人員,然后讓他們檢查一下監聽消息中間件的線程是不是被什么意外給打斷了,導致服務端不會再去處理任何消息。最終在后續的排查中,發現消息隊列當中,確實堆積了大量的消息沒有處理,而服務端的代碼當中,是使用線程池處理的消息,目前還沒有定論。不過LZ基本斷定,這些監聽的線程肯定在某種情況下會被終止。

  之后LZ就只需要等待A組人員的排查結果了,事實證明,LZ的系統其實是沒有問題的。不過有一點是應該改進的,那就是行級鎖的問題。因此后來LZ將消息的發送和數據的更新調換了次序,這樣可以徹底避免行級鎖的產生,哪怕是再次出現這個問題,至少不會因為行級鎖造成的數據庫壓力,而壓垮整個數據庫服務器。

 

未完待續

 

  盡管此次基本上已經掌握了問題出現的原因,但其實最根源的地方還是沒找到,那就是A組系統當中,究竟何時會中斷監聽線程。只要這個問題找到了,那么以后就可以防患於未然了。至今為止,A組成員還在尋找問題根源,不過最終的結果可能是,像LZ第一次碰到的時候一樣,不了了之。但是還是那句話,“出來混,遲早是要還的”。


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM