做者：陶建輝node
這是我在 2020 年 5 月寫的一篇內部博客，當時是但願研發和技術支持同窗可以幫助用戶快速定位 Bug，解決問題。2020 年 12 月我又迭代了一版，並還針對此進行了內部的培訓。這段時間我也一直在關注微信羣中的提問，發現有很多用戶以爲分析 TDengine 的日誌或任何其餘分佈式系統的日誌是有難度的。如今將我這篇博客公開，以分析 TDengine 的日誌爲例，介紹一套方法，若是你能掌握，那麼分析分佈式系統的日誌就會變得極其之簡單。shell
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 控制，具體各模塊的參數以及日誌顯示的模塊名以下：url
若是嫌配置參數過多，最簡單的方式，是設置 debug 的總參數 debugFlag, 這個參數設置後，除 tmr 日誌外，全部模塊的 debug 所有統一設置爲同一個參數 debugFlag。debugFlag 的默認值爲 0，當 debugFlag 爲非 0 值時，將會覆蓋全部的日誌配置參數。
除非特殊 case, 不建議設置 util, timer 的 debugFlag 爲 135，設置爲 131 合適。spa
日誌文件
TDengine 會生成客戶端以及服務器端日誌，存放在日誌目錄裏，缺省日誌目錄是/var/log/taos, 但能夠經過修改 taos.cfg 裏的配置參數 logDir 指定
- 客戶端日誌文件名爲 taoslogY.X (由於能夠運行多個客戶端，所以一臺機器上能夠生成多個日誌文件）
- 服務器端日誌文件爲 taosdlog.X
日誌文件的大小有控制，達到必定行數（taos.cfg 裏配置參數 numOfLogLines 控制）後，會生成新的日誌文件。但 TDengine 僅僅保留兩個日誌文件，文件名以 0 或 1 結尾，交替。
日誌格式：
日誌文件，從左到右，分爲四大塊
- 時間戳，精確到微妙
- 線程 ID，由於是多線程，這個參數很重要，由於只有同一個線程輸出的日誌纔是有時序保證的，是按設計的 flow 輸出的
- 模塊名，三個字母
- 每一個模塊輸出的日誌
分析日誌的幾大步驟
當測試或客戶報告一個 Bug，不管是手動仍是自動，都是執行某個具體操做發生的。這個具體操做通常都是執行一個 SQL 語句。這個問題多是客戶端致使，也多是服務器代碼致使。下面以 create table 爲例，解釋日誌的分析，爲便於聚焦解釋，圖中去掉時間戳。
先看客戶端
最早須要查看的是客戶端日誌，示例截圖以下：
- 先找到出問題的 SQL 語句，在客戶端日誌裏搜索 「SQL: 「，就能夠看到(截圖第二行）。日誌裏搜索「SQL result:」（截圖第 11 行）, 若是成功，會顯示 」SQL result:success」, 不然會顯示「SQL result: xxxx」, 其中 xxxx 是錯誤信息。如何快速找到失敗的 SQL，須要知道大概的時間範圍，SQL 語句是什麼，這麼搜索會很快。
- taoc 的日誌數據，有個很重要的參數是 pSql，是分配給內部 SQL Obj 的一個地址。taosc 把這個地址信息放在全部 taosc 日誌的最前面，緊接 TSC 以後。這個值很關鍵，是傳統客戶端與服務器日誌的關鍵。在上面的截圖中，用綠色背景標出。
- pSql 這個參數會做爲 ahandle 傳遞至 RPC 模塊，RPC 在全部消息裏，都會將其打印處理（綠色背景）。由於不少模塊都會調用 RPC 模塊，RPC 也會把誰調用的打印出來，好比截圖中，是 TSC 調用的，就會打印 RPC TSC 出來。
- RPC 會把消息 create-table 發往服務器，RPC 日誌會打印出來（截圖第 8 行), 告知發往到了哪一個 dnode 的 End Point, 截圖中顯示發往了 hostname: 9be7010a917e, port 爲 6030。若是有問題，那咱們就須要檢查這個 End Point 所在的服務器日誌了。
- 能看到，RPC 模塊收到了服務器的迴應，但爲避免轉換消耗資源，日誌僅僅顯示了 16 進制的 IP 地址（截圖第 9 行，0x20012ac)以及端口號。RPC 模塊的日誌很關鍵，由於它把各個邏輯節點串通起來。
再看服務器
分析了客戶端日誌，服務器日誌很關鍵，下面仍然以 create-table 爲例，請看截圖:
- 從客戶端日誌裏，找到 pSql，值是 0x5572c4fab3a0，所以在 taosdlog 裏直接搜索 0x5572c4fab3a0，就能夠看到截圖中綠色背景的日誌。所以 pSql 是將客戶端與服務器日誌串起來很重要的參數。
- 對於 create-table 這個具體操做而言，是有 mnode 處理。截圖中，是由於建立第一張表，所以須要先建立 vnode, 而後建立 table 等系列操做，牽涉到不少模塊，就不細解釋。
- 最後，mnode 建立完 table, 經過 RPC 模塊發回 response(截圖第 52 行，最後一行），所以能夠清晰的看出服務器工做正常。
注意：dnode 模塊收到消息後，會根據消息類型，將消息分發到 mnode, vnode 的消息隊列。而後工做線程會消費消息隊列裏的消息，對消息進行處理。對於 vnode 而言，裏面的子模塊 tsdb, wal, sync, cq 都是單線程執行的，所以在找到 pSql 以後（截圖第二行），須要根據線程的 ID，順序往下看，就能知道整個流程，很好分析。
幾個關鍵點
- 先找到失敗 SQL 語句
- 找到 pSql 的值，拷貝下來, 假設爲 xxxxx
- grep 「xxxxx」 taoslogx.x, 找到與這條 SQL 相關的客戶端日誌，看可否找到問題
- 打開 taosdlog 服務器日誌，搜索 pSql 的值 xxxxx, 檢查時間戳，看是不是失敗的那條操做
- 而後分析服務器日誌
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 傳至服務器側，這樣客戶端與服務器的日誌匹配將大大加速。
熟悉日誌的方法
- 首先要了解 TDengine 的設計，瞭解每一個主要操做的流程。
- 打開全部日誌開關(將 debugFlag 設爲 135), 全部的 SQL 語句都執行一次，對照每條 SQL，檢查對應的客戶端與服務器日誌。
查看客戶端執行的 SQL 語句
客戶端會產生不少日誌，查看執行的 SQL 語句，便於分析和重複問題。找出系統到底執行了什麼樣的 SQL 語句，有幾種方法
- 若是客戶端日誌打開，執行: grep 「SQL: 」 taoslog*, 會看到日誌中全部執行的 SQL 語句。
- 若是用 taos，手工執行 SQL 語句，請在 home 目錄裏，查看隱藏的文件.taos_history, 裏面會有 taos 執行的全部歷史命令。
- 對客戶端進行配置，在配置文件中，將 tscEnableRecordSql 參數設置爲 1，即將客戶端輸入的 SQL 語句打印到單獨的文件（tscnote-xxxx.0，xxxx 是 pid），與客戶端日誌所在目錄相同。
- 對於 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