60秒定位問題，十倍程序員的Debug日常有哪些

這篇文章將為大家詳細講解有關60秒定位問題，十倍程序員的Debug日常有哪些，文章內容質量較高，因此小編分享給大家做個參考，希望大家閱讀完這篇文章后對相關知識有一定的了解。

TDengine 是一個集群系統，任何一個操作，都會涉及到 APP、taosc、mnode 和 vnode 等邏輯節點。這些節點之間是通過 Socket 進行通訊的。而且在測試中，可能有多個 TDengine 實例，這讓分析變得更為復雜。對于一個操作，如何將不同邏輯節點的日志匹配串通起來，高效過濾處理，成為分析問題的關鍵。

打開相關日志開關

TDengine 每個獨立的模塊都有自己的 debugFlag, 包括 taosc, dnode, vnode, mnode, tsdb, wal, sync, query, rpc, timer 等。目前每個模塊的日志輸出可以控制到：

• Fatal/Error，錯誤，日志上會顯示 ERROR

• Warning，警告, 日志上會顯示 WARN

• Info，重要信息

• Debug，一般信息

• Trace，非常詳細且反復出現的調試信息

• Dump，原始數據

輸出的日志可以控制輸出到：

• 文件

• 屏幕

上述的控制全部由 debugFlag 的一個字節控制，這個字節里的 bit 圖如下：

因此，如果要將 error, warning, info,debug 輸出到日志文件，那么 debug 要設置為：135；如果還想輸出 trace 級別的日志，那么 debug 要設置為：143；如果僅僅輸出 error 和 warning, debug 設置為 131。正常情況下，建議將 debug 設置為 135 即可。

每個模塊的 debug flag 的設置全部由配置文件 taos.cfg 控制，具體各模塊的參數以及日志顯示的模塊名如下：

如果嫌配置參數過多，最簡單的方式，是設置 debug 的總參數 debugFlag, 這個參數設置后，除 tmr 日志外，所有模塊的 debug 全部統一設置為同一個參數 debugFlag。debugFlag 的默認值為 0，當 debugFlag 為非 0 值時，將會覆蓋所有的日志配置參數。
除非特殊 case, 不建議設置 util, timer 的 debugFlag 為 135，設置為 131 合適。

日志文件

TDengine 會生成客戶端以及服務器端日志，存放在日志目錄里，缺省日志目錄是/var/log/taos, 但可以通過修改 taos.cfg 里的配置參數 logDir 指定

• 客戶端日志文件名為 taoslogY.X (因為可以運行多個客戶端，因此一臺機器上可以生成多個日志文件）

• 服務器端日志文件為 taosdlog.X

日志文件的大小有控制，達到一定行數（taos.cfg 里配置參數 numOfLogLines 控制）后，會生成新的日志文件。但 TDengine 僅僅保留兩個日志文件，文件名以 0 或 1 結尾，交替。

日志格式：

日志文件，從左到右，分為四大塊

1. 時間戳，精確到微妙

2. 線程 ID，因為是多線程，這個參數很重要，因為只有同一個線程輸出的日志才是有時序保證的，是按設計的 flow 輸出的

3. 模塊名，三個字母

4. 每個模塊輸出的日志

分析日志的幾大步驟

當測試或客戶報告一個 Bug，無論是手動還是自動，都是執行某個具體操作發生的。這個具體操作一般都是執行一個 SQL 語句。這個問題可能是客戶端導致，也可能是服務器代碼導致。下面以 create table 為例，解釋日志的分析，為便于聚焦解釋，圖中去掉時間戳。

先看客戶端

最先需要查看的是客戶端日志，示例截圖如下：

1. 先找到出問題的 SQL 語句，在客戶端日志里搜索 “SQL: “，就可以看到(截圖第二行）。日志里搜索“SQL result:”（截圖第 11 行）, 如果成功，會顯示 ”SQL result:success”, 否則會顯示“SQL result: xxxx”, 其中 xxxx 是錯誤信息。如何快速找到失敗的 SQL，需要知道大概的時間范圍，SQL 語句是什么，這么搜索會很快。

2. taoc 的日志數據，有個很重要的參數是 pSql，是分配給內部 SQL Obj 的一個地址。taosc 把這個地址信息放在所有 taosc 日志的最前面，緊接 TSC 之后。這個值很關鍵，是傳統客戶端與服務器日志的關鍵。在上面的截圖中，用綠色背景標出。

3. pSql 這個參數會作為 ahandle 傳遞至 RPC 模塊，RPC 在所有消息里，都會將其打印處理（綠色背景）。因為很多模塊都會調用 RPC 模塊，RPC 也會把誰調用的打印出來，比如截圖中，是 TSC 調用的，就會打印 RPC TSC 出來。

4. RPC 會把消息 create-table 發往服務器，RPC 日志會打印出來（截圖第 8 行), 告知發往到了哪個 dnode 的 End Point, 截圖中顯示發往了 hostname: 9be7010a917e, port 為 6030。如果有問題，那我們就需要檢查這個 End Point 所在的服務器日志了。

5. 能看到，RPC 模塊收到了服務器的回應，但為避免轉換消耗資源，日志僅僅顯示了 16 進制的 IP 地址（截圖第 9 行，0x20012ac)以及端口號。RPC 模塊的日志很關鍵，因為它把各個邏輯節點串通起來。

再看服務器

分析了客戶端日志，服務器日志很關鍵，下面仍然以 create-table 為例，請看截圖:

1. 從客戶端日志里，找到 pSql，值是 0x5572c4fab3a0，因此在 taosdlog 里直接搜索 0x5572c4fab3a0，就可以看到截圖中綠色背景的日志。因此 pSql 是將客戶端與服務器日志串起來很重要的參數。

2. 對于 create-table 這個具體操作而言，是有 mnode 處理。截圖中，是因為創建第一張表，因此需要先創建 vnode, 然后創建 table 等系列操作，牽涉到很多模塊，就不細解釋。

3. 最后，mnode 創建完 table, 通過 RPC 模塊發回 response(截圖第 52 行，最后一行），因此可以清晰的看出服務器工作正常。

注意：dnode 模塊收到消息后，會根據消息類型，將消息分發到 mnode, vnode 的消息隊列。然后工作線程會消費消息隊列里的消息，對消息進行處理。對于 vnode 而言，里面的子模塊 tsdb, wal, sync, cq 都是單線程執行的，因此在找到 pSql 之后（截圖第二行），需要根據線程的 ID，順序往下看，就能知道整個流程，很好分析。

幾個關鍵點

1. 先找到失敗 SQL 語句

2. 找到 pSql 的值，拷貝下來, 假設為 xxxxx

3. grep “xxxxx” taoslogx.x, 找到與這條 SQL 相關的客戶端日志，看能否找到問題

4. 打開 taosdlog 服務器日志，搜索 pSql 的值 xxxxx, 檢查時間戳，看是否是失敗的那條操作

5. 然后分析服務器日志

RPC 模塊的消息十分關鍵。有一點很重要，對于每一條 RPC 消息，都會打印 parse code: xx, 這是協議解析結果，0 表示沒有問題，其他值說明協議解析就不成功。但同時，消息本身還有 code: 0xXX, 這是發送方帶來的錯誤碼，一般是服務器發往客戶端的，正確的話，code 是 0，否則就是報錯。

另外一個日志匹配方法

客戶端通過 RPC 模塊發出一條消息時，日志上帶有類似

sig:0x01000000:0x01000000:55893

這是 RPC 的 source ID, dest ID, 以及 transcation ID，三個參數組合在一起，能唯一標識來自一個客戶端的鏈接。每條新消息的發送，都會將 transcation ID 加一，因此在一段時間內具有唯一性（transcation ID 是兩字節，會循環的)。

1.6 版本只能依賴 sig 這個字符串將客戶端與服務器日志匹配起來，但需要看很多上下文，因此麻煩，效率不夠。

2.0 版將 pSql 傳至服務器側，這樣客戶端與服務器的日志匹配將大大加速。

熟悉日志的方法

1. 首先要了解 TDengine 的設計，了解每個主要操作的流程。

2. 打開所有日志開關(將 debugFlag 設為 135), 所有的 SQL 語句都執行一次，對照每條 SQL，檢查對應的客戶端與服務器日志。

查看客戶端執行的 SQL 語句

客戶端會產生很多日志，查看執行的 SQL 語句，便于分析和重復問題。找出系統到底執行了什么樣的 SQL 語句，有幾種方法

1. 如果客戶端日志打開，執行: grep “SQL: ” taoslog*, 會看到日志中所有執行的 SQL 語句。

2. 如果用 taos，手工執行 SQL 語句，請在 home 目錄里，查看隱藏的文件.taos_history, 里面會有 taos 執行的所有歷史命令。

3. 對客戶端進行配置，在配置文件中，將 tscEnableRecordSql 參數設置為 1，即將客戶端輸入的 SQL 語句打印到單獨的文件（tscnote-xxxx.0，xxxx 是 pid），與客戶端日志所在目錄相同。

4. 對于 resetful 接口，在 taosd 的配置文件中將 httpEnableRecordSql 參數設置為 1， 會將 htpp 請求打印到單獨的文件（httpnote.0），與服務端日志所在目錄相同。

動態修改日志

有時不能重啟服務器或客戶端，但日志的設置又不正確，這個時候需要動態設置，執行如下幾步：

show dnodes；// 查找每個 dnode 的 ID
alter dnode id debugFlag 143;  // 設置相應的 debugFlag

其中第二步的 id 是第一步獲取的。

有時需要把后續日志輸出到一個新文件，方便日志的查看及搜索，執行：

alter dnode id resetlog;

有時 shell 根本鏈接不上，這時可以在 taosd 運行的機器，給進程發送 SIGUSR1 命令，如：

kill -SIGUSR1 pidxxx

關于60秒定位問題，十倍程序員的Debug日常有哪些就分享到這里了，希望以上內容可以對大家有一定的幫助，可以學到更多知識。如果覺得文章不錯，可以把它分享出去讓更多的人看到。