我們的一個(gè)系統(tǒng)最近更換了測(cè)試環(huán)境，剛上線就發(fā)現(xiàn)一個(gè)奇怪的問題——每個(gè)SQL查詢都至少要延時(shí)7-10秒之后才會(huì)有反應(yīng)。

系統(tǒng)使用的是Oracle數(shù)據(jù)庫(kù)，雖然沒有使用數(shù)據(jù)庫(kù)連接池但是也不應(yīng)該會(huì)有“10的秒延時(shí)”，我Debug了Oracle的客戶端庫(kù)，發(fā)現(xiàn)客戶端的停頓是出現(xiàn)在等待網(wǎng)絡(luò)數(shù)據(jù)，通過tcpdump抓取TNS數(shù)據(jù)包再次印證了這一點(diǎn)——有10秒鐘的時(shí)間再等待服務(wù)器端返回?cái)?shù)據(jù)包。

所以問題可以確定是出現(xiàn)在Oracle服務(wù)器上面。回想了一下Oracle的架構(gòu)，TNS是負(fù)責(zé)響應(yīng)用戶請(qǐng)求轉(zhuǎn)發(fā)請(qǐng)求到實(shí)例，所以對(duì)于Oracle來說它可以啟動(dòng)多個(gè)TNS提高系統(tǒng)的“并發(fā)能力”。(非常巧妙的設(shè)計(jì))TNS提供的配置選項(xiàng)非常少，基本上沒有什么參數(shù)可以調(diào)整(你可以查看完整的listener.ora配置，基本上都是對(duì)網(wǎng)絡(luò)傳輸?shù)囊恍﹥?yōu)化)，幾乎陷入了死局。

有時(shí)候解決問題就是這樣，知道問題出現(xiàn)某個(gè)部分但是限于沒有這部分的源代碼或者時(shí)間不允許我們?nèi)シ创a往往只能通過“猜”->“試”的辦法去“暴力破解”。一般這種情況下我會(huì)選擇一種不一樣的Debug方法——通過一些工具去獲知系統(tǒng)的內(nèi)部執(zhí)行軌跡比如獲知系統(tǒng)調(diào)用，這種方法一般情況下都非常有效。

祭出大殺器—— strace，這是Linux下的一個(gè)小工具可以跟蹤某個(gè)進(jìn)程的系統(tǒng)調(diào)用，通過參數(shù)p可以指定PID。f參數(shù)會(huì)跟蹤fork出來的線程或者子進(jìn)程;r參數(shù)會(huì)輸出系統(tǒng)調(diào)用的執(zhí)行時(shí)間。也有人喜歡用DTrace，我覺得這玩意太重，動(dòng)不動(dòng)就得寫一個(gè)腳本啥的。不可否認(rèn)它要比strace牛B多了，但是我只是想看一下系統(tǒng)調(diào)用——所以strace足夠了。

執(zhí)行strace -fr -p 19535其中19535是TNS的PID。

輸出分為三列，***列是PID，第二列是執(zhí)行時(shí)間，第三列是執(zhí)行的系統(tǒng)調(diào)用和傳遞的參數(shù)。我們直接看可疑的部分：

日志里面有兩個(gè)PID，19535是TNS的主進(jìn)程，20358是TNS為每個(gè)連接開辟的“線程”。最下面有2秒鐘的Timeout，原因是poll超時(shí)，往上不難分析：

TNS主進(jìn)程接收到用戶請(qǐng)求后會(huì)新建一個(gè)線程(本例是20358)，這個(gè)線程有一段邏輯打開了202.96.209.133這臺(tái)服務(wù)器的53端口(***個(gè)紅箭頭)然后發(fā)送了一段數(shù)據(jù)(第二個(gè)紅箭頭)，等待服務(wù)器響應(yīng)(超時(shí)時(shí)間是5秒，poll的***一個(gè)參數(shù))。本例中的10秒延時(shí)就是由于這里的Timeout引起的(一共嘗試兩次)

202.96.209.133這臺(tái)服務(wù)器是我配置的DNS地址，53端口則是DNS服務(wù)器監(jiān)聽的端口，有意思的是sendto函數(shù)的數(shù)據(jù)部分——這就是一個(gè)DNS“查詢數(shù)據(jù)包”(前12個(gè)固定頭+Question數(shù)據(jù)包)。查詢的域名——kvm則是我本機(jī)的計(jì)算機(jī)名。需要特別注意的是我的hosts文件已經(jīng)配置了本機(jī)地址和kvm的對(duì)應(yīng)，如果按照hostbyname這種dns方法來查詢機(jī)器名是可以正常拿到本機(jī)IP的。而Oracle做了一個(gè)有意思的決定——它的DNS解析不依賴于本機(jī)hosts配置而是直接讀取/etc/resolv.conf獲知dns server地址自己構(gòu)造DNS“查詢數(shù)據(jù)包”完成的域名解析。

解決辦法也很簡(jiǎn)單，把/etc/resolv.conf清空就行了(或則自己搞一個(gè)內(nèi)部DNS地址，總之讓Oracle可以正常DNS查詢或者干脆快速的解析出錯(cuò)就行了)。

Oracle為什么會(huì)有這個(gè)動(dòng)作我估計(jì)是因?yàn)樗募軜?gòu)中允許TNS和實(shí)例分離，這個(gè)解析動(dòng)作其實(shí)是在解析實(shí)例所對(duì)應(yīng)的IP地址。

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

分辨出19535誰(shuí)是主線程誰(shuí)是派生的20358其實(shí)但從數(shù)字就能判斷出來，Linux是從小到大分配PID的，所以——"大"的肯定是子線程。不過為了更加“科學(xué)”我還是找到信息來印證一下

clone方法其實(shí)就是Linux的“new thread”函數(shù)，***一個(gè)參數(shù)指定了線程的“函數(shù)入口”。 這里非常奇怪，TNS會(huì)派生出一個(gè)20357的線程，然后20357派生出20358就“自殺”了，兩次派生的函數(shù)入口是同一地址。這一點(diǎn)我也搞不太清楚為什么。

【本文是51CTO專欄作者邢森的原創(chuàng)文章，轉(zhuǎn)載請(qǐng)聯(lián)系作者本人獲取授權(quán)】

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