以業(yè)務(wù)連續(xù)性為目的運(yùn)維一例

IT那活兒發(fā)布于2023-01-11 13:20 / 790人閱讀

在我們?nèi)粘＿\(yùn)維過(guò)程中，經(jīng)常會(huì)遇到兩種類型的運(yùn)維人員，一種是證明自己負(fù)責(zé)的業(yè)務(wù)組件框架沒(méi)問(wèn)題后就事不關(guān)己，高高掛起；另一種是，即便不是自己本職范圍內(nèi)的業(yè)務(wù)組件框架，或者自己負(fù)責(zé)的框架不是性能故障的根因，但只要能以自己的能力知識(shí)去幫助解決問(wèn)題，就以一種不到黃河心不死的精神，全力協(xié)助上游或下游進(jìn)行問(wèn)題查找，直到業(yè)務(wù)恢復(fù)。其實(shí)，自己一畝三分地維護(hù)地再好，業(yè)務(wù)就是無(wú)法使用，站在全局的角度，有價(jià)值嗎？所以，本著業(yè)務(wù)可用性，業(yè)務(wù)連續(xù)性的運(yùn)維才是運(yùn)維人該有的思想覺悟，也是運(yùn)維人的最終價(jià)值之一。下面的案例介紹了如何基于數(shù)據(jù)庫(kù)，以抽絲剝繭鉆牛角尖精神，最終幫助業(yè)務(wù)側(cè)定位到了業(yè)務(wù)中斷問(wèn)題的根因（業(yè)務(wù)邏輯問(wèn)題）。

背景

現(xiàn)場(chǎng)反饋某一項(xiàng)業(yè)務(wù)在大版本上線之后無(wú)法辦理。開發(fā)人員首先懷疑是程序中的某條SQL執(zhí)行較慢導(dǎo)致業(yè)務(wù)辦理超時(shí)，于是先配合開發(fā)人員在數(shù)據(jù)庫(kù)中抓取高耗SQL。在抓取高耗SQL的過(guò)程中，高耗SQL是沒(méi)有抓到，卻意外的抓到了一把“鎖”（如下圖），這把“鎖”只有WAITER，卻沒(méi)有發(fā)現(xiàn)HOLDER。于是就有了接下來(lái)的故事。

尋找HOLDER

在配合開發(fā)人員進(jìn)行業(yè)務(wù)測(cè)試抓取高耗SQL的過(guò)程中，發(fā)現(xiàn)每一次該業(yè)務(wù)發(fā)起的時(shí)候，數(shù)據(jù)庫(kù)中總會(huì)出現(xiàn)一條enq:TX - row lockcontention的等待事件。但奇怪的是這個(gè)TX鎖中只有WAITER,并沒(méi)有持有鎖的HOLDER，于是將該等待事件中的SQL語(yǔ)句（如下圖）發(fā)給開發(fā)側(cè)確認(rèn)。

開發(fā)側(cè)也從程序錯(cuò)誤日志中找到了該條SQL，由此可以初步判斷導(dǎo)致業(yè)務(wù)處理無(wú)法閉環(huán)的原因應(yīng)該是在執(zhí)行該UPDATE語(yǔ)句時(shí)出現(xiàn)TX鎖堵塞導(dǎo)致。但是究竟是誰(shuí)持有了鎖，導(dǎo)致UPDATE語(yǔ)句執(zhí)行不下去呢？首先按照開發(fā)人員抓取的剛剛辦理業(yè)務(wù)時(shí)傳入的綁定變量手動(dòng)執(zhí)行了該UPDATE語(yǔ)句，看是否會(huì)有TX鎖出現(xiàn)。結(jié)果如下圖：

可以看到手動(dòng)執(zhí)行該UPDATE語(yǔ)句可以執(zhí)行成功，沒(méi)有出現(xiàn)TX鎖。進(jìn)一步排查該表是否有唯一約束，如果有唯一約束，程序在同一個(gè)事務(wù)里更新了兩次同一記錄也會(huì)產(chǎn)生TX鎖，于是查看了該表上的索引（如下圖）

可以發(fā)現(xiàn)該表的主鍵列在UPDATE語(yǔ)句中并沒(méi)有修改，可以排除這一可能。那會(huì)不會(huì)是該表上存在TRIGGER，在更新的時(shí)候會(huì)觸發(fā)某一條件導(dǎo)致出現(xiàn)TX鎖呢？

查詢?cè)摫淼囊蕾噷?duì)象發(fā)現(xiàn)只有FUNCTION和PROCEDURE,并沒(méi)有TRIGGER,以上常見導(dǎo)致TX原因均被推翻，尋找HOLDER陷入了僵局。

發(fā)現(xiàn)HOLDER

尋找HOLDER陷入僵局，但問(wèn)題還得接著排查，為了能更多的發(fā)現(xiàn)相關(guān)線索，請(qǐng)求開發(fā)側(cè)多做幾單業(yè)務(wù)，以便于測(cè)試過(guò)程的跟蹤。平臺(tái)這邊也從之前的以表為中心來(lái)尋找問(wèn)題轉(zhuǎn)為以跟蹤數(shù)據(jù)庫(kù)對(duì)應(yīng)的業(yè)務(wù)SESSION信息來(lái)定位問(wèn)題，看看能否從SESSION中獲取到更有價(jià)值的線索信息。

開發(fā)在做第一單測(cè)試業(yè)務(wù)時(shí)，我們將WAITER的相關(guān)SESSION做了PROCESSDUMP,然而從DUMP下來(lái)的TRACE文件中并沒(méi)有發(fā)現(xiàn)有異常。于是又讓開發(fā)做了第二單測(cè)試單據(jù)，第二單元測(cè)試的過(guò)程中，查詢數(shù)據(jù)庫(kù)相關(guān)視圖發(fā)現(xiàn)被鎖的表上同時(shí)有三個(gè)SESSION在訪問(wèn)，這引起了我們的注意。

WAITER明明是一個(gè)SESSION，為什么會(huì)有3個(gè)SESSION在訪問(wèn)呢，我們接著查看了這3個(gè)SESSION的信息（如下圖）

除了WAITER的SESSION之外，另外兩個(gè)會(huì)話均為INACTIVE狀態(tài)，說(shuō)明SQL已經(jīng)執(zhí)行完成。而其中為mainsrv程序發(fā)起的會(huì)話，主機(jī)名剛好和WAITERSESSION的主機(jī)名相同，這不免讓人產(chǎn)生懷疑，這兩個(gè)會(huì)話之間是否具有某種聯(lián)系？

帶著疑問(wèn)，我們讓開發(fā)人員繼續(xù)做了2單業(yè)務(wù)進(jìn)行測(cè)試，結(jié)果與我們推測(cè)一致。每次在業(yè)務(wù)發(fā)起的時(shí)候，被鎖的表上均會(huì)有2個(gè)相同主機(jī)發(fā)起的兩個(gè)不同程序的SESSION（如下圖）

其中mainsrv程序的SESSION每次狀態(tài)均為INACTIVE，而ordsrv程序的SESSION（即WAITERSESSION）每次狀態(tài)均為ACTIVE。由此可以初步推斷可能是由于mainsrv程序執(zhí)行了某一SQL后可能導(dǎo)致之后的ordsrv程序執(zhí)行的UPDATE語(yǔ)句堵塞。于是緊接著我們對(duì)mainsrv和ordsrv的SESSION做了PROCESSDUMP。此時(shí)，莫名有些興奮，感覺HOLDER似乎離我們?cè)絹?lái)越近了，真相也離我們?cè)絹?lái)越近了。

定位BUG

在對(duì)mainsrv和ordsrv的SESSION做了PROCESSDUMP后，馬上對(duì)兩個(gè)TRACE文件進(jìn)行了分析排查。果然在mainsrv程序的TRACE文件中發(fā)現(xiàn)了與ordsrv程序TRACE文件中幾乎相同的SQL，原來(lái)mainsrv程序和ordsrv程序更新了相同的表，如圖（上圖為mainsrv程序的SQL，下圖為ordsrv程序的SQL）

由此基本可以斷定導(dǎo)致該業(yè)務(wù)辦理超時(shí)的原因是:首先是mainsrv程序執(zhí)行了UPDATE語(yǔ)句更新****_worklist表某一行數(shù)據(jù)，之后在同一個(gè)事務(wù)中跨服務(wù)調(diào)用了ordsrv程序，ordsrv程序也更新了****_worklist表同一行的數(shù)據(jù)。最終導(dǎo)致我們?cè)跀?shù)據(jù)庫(kù)中查詢到同時(shí)有2個(gè)SESSION訪問(wèn)了****_worklist表，mainsrv程序的SESSION狀態(tài)為INACTIVE是mainsrv先執(zhí)行完了UPDATE語(yǔ)句，ordsrv程序的SESSION狀態(tài)為ACTIVE是由于被mainsrv執(zhí)行的語(yǔ)句所堵塞，所以一直在等待鎖的釋放，直到程序超時(shí)。

將診斷結(jié)論發(fā)于開發(fā)側(cè)核實(shí)，在開發(fā)側(cè)排查代碼后證實(shí)結(jié)論完全正確。至此，該問(wèn)題根因找到，在開發(fā)側(cè)發(fā)版整改業(yè)務(wù)邏輯后，問(wèn)題徹底解決。本次分享到此結(jié)束，我們下次再見。