作者：陶建輝

這是我在 2020 年 5 月寫的一篇內部部落格，當時是希望研發和技術支援同學能夠幫助使用者快速定位 Bug，解決問題。2020 年 12 月我又迭代了一版，並還針對此進行了內部的培訓。這段時間我也一直在關注微信群中的提問，發現有不少使用者覺得分析 TDengine 的日誌或任何其他分散式系統的日誌是有難度的。現在將我這篇部落格公開，以分析 TDengine 的日誌為例，介紹一套方法，如果你能掌握，那麼分析分散式系統的日誌就會變得極其之簡單。

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

本文總結了一套方法，能夠讓大家快速找到 Bug 所在。

開啟相關日誌開關

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

原文首發於：https://mp.weixin.qq.com/s/LUz1niYajOR35UpOlf