我們的一個系統最近更換了測試環境，剛上線就發現一個奇怪的問題——每個SQL查詢都至少要延時7-10秒之后才會有反應。

系統使用的是Oracle數據庫，雖然沒有使用數據庫連接池但是也不應該會有“10的秒延時”，我Debug了Oracle的客戶端庫，發現客戶端的停頓是出現在等待網絡數據，通過tcpdump抓取TNS數據包再次印證了這一點——有10秒鐘的時間再等待服務器端返回數據包。

所以問題可以確定是出現在Oracle服務器上面。回想了一下Oracle的架構，TNS是負責響應用戶請求轉發請求到實例，所以對于Oracle來說它可以啟動多個TNS提高系統的“并發能力”。(非常巧妙的設計)TNS提供的配置選項非常少，基本上沒有什么參數可以調整(你可以查看完整的listener.ora配置，基本上都是對網絡傳輸的一些優化)，幾乎陷入了死局。

有時候解決問題就是這樣，知道問題出現某個部分但是限于沒有這部分的源代碼或者時間不允許我們去翻源代碼往往只能通過“猜”->“試”的辦法去“暴力破解”。一般這種情況下我會選擇一種不一樣的Debug方法——通過一些工具去獲知系統的內部執行軌跡比如獲知系統調用，這種方法一般情況下都非常有效。

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

執行strace -fr -p 19535其中19535是TNS的PID。

輸出分為三列，***列是PID，第二列是執行時間，第三列是執行的系統調用和傳遞的參數。我們直接看可疑的部分：

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

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

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

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

Oracle為什么會有這個動作我估計是因為它的架構中允許TNS和實例分離，這個解析動作其實是在解析實例所對應的IP地址。

小發現

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

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

【本文是51CTO專欄作者邢森的原創文章，轉載請聯系作者本人獲取授權】

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