作者簡介
劉江，伴魚英語數(shù)據(jù)庫負(fù)責(zé)人，TUG 2020 年度 MOA。負(fù)責(zé)伴魚數(shù)據(jù)庫運維、大數(shù)據(jù)運維以及數(shù)據(jù)庫平臺化建設(shè)。
本文來自于伴魚英語 DBA 組負(fù)責(zé)人劉江在「能量鈦」第二期活動的分享，劉江為大家分享了 TiDB 慢日志在伴魚的實踐。本文將從以下三個方面展開：
第二部分介紹下慢日志系統(tǒng)具體是怎么做的；
背景與需求
今年上半年，阿里云發(fā)布了新一代 DAS（數(shù)據(jù)庫自治服務(wù)）服務(wù)，里面談到數(shù)據(jù)庫的問題，90% 以上的問題都是來源于數(shù)據(jù)庫的異常請求。其實在我們?nèi)粘５臄?shù)據(jù)庫問題場景，大部分的問題也都是異常 SQL 請求，像數(shù)據(jù)庫的 bug 或者是機(jī)器導(dǎo)致的故障問題，平時遇到還是相對較少的。對于異常 SQL 的定位，數(shù)據(jù)庫的慢日志分析，是一種特別有效的手段。
那么我們在平時利用慢日志分析問題的時候，會有哪些痛點？在做慢日志系統(tǒng)之前，集群的慢日志是分布在多臺機(jī)器上面的，如果數(shù)據(jù)庫出現(xiàn)了問題，就需要登錄到多臺機(jī)器一臺臺的去分析，問題處理的效率很低。特別是當(dāng)集群規(guī)模特別大的時候，基本上沒辦法去快速定位問題。
當(dāng)然，TiDB 在 4.0 版本支持了 Dashboard，我們可以通過 Dashboard 查看整個集群的慢日志信息，比如最近 15 分鐘的或者最近半個小時的慢日志。但當(dāng)系統(tǒng)真正出現(xiàn)問題的時候，慢日志會特別多，Dashboard 會面臨計算加載等性能問題，同時 Dashboard 不支持檢索和分析統(tǒng)計，這不利于我們快速定位到異常 SQL。
TiDB 系統(tǒng)庫自帶了一張表（INFORMATION_SCHEMA.SLOW_QUERY）來實時存儲慢日志，我們也可以通過它來定位異常SQL，但這張表是一個關(guān)系型的表，本身是沒有索引的，當(dāng)日志量特別大的時候，多維檢索和分析是特別慢的。同時，對于關(guān)系型表的多維檢索和分析統(tǒng)計，也不是它所擅長的。
基于以上的痛點，伴魚的慢日志系統(tǒng)需要滿足以下幾個需求：
首先，就是慢日志集中式收集，能夠把線上多個集群甚至幾十個集群的慢日志全部收攏在一起，便于集中分析，這樣做入口就統(tǒng)一了。
其次，要保證收集的慢日志是準(zhǔn)實時的。因為如果收集的慢日志延遲太大的話，對于處理線上問題和分析問題是沒有幫助的。
然后，慢日志可以檢索和統(tǒng)計分析。因為當(dāng)出現(xiàn)問題的時候慢日志是特別多的，這個時候如果能夠檢索和統(tǒng)計分析的話，就可以快速定位到異常 SQL。
最后，慢日志系統(tǒng)需要支持監(jiān)控和告警。
系統(tǒng)詳解
基于以上的背景和需求，我們來看一下伴魚的慢日志系統(tǒng)是怎么做的。
系統(tǒng)架構(gòu)
伴魚慢日志系統(tǒng)整體架構(gòu)，如下圖所示。我們在 TiDB Server 機(jī)器初始化時部署了 Filebeat 組件，通過它把采集的慢日志，寫入到 Kafka，同時打上機(jī)器 IP 信息。然后通過 logstash 解析出我們關(guān)注的字段，存儲到 ES。ES 本身是一個搜索引擎，做數(shù)據(jù)的分析和統(tǒng)計，速度是特別快的。同時我們通過 Kibana 查看 ES 里的慢日志數(shù)據(jù)，做可視化的統(tǒng)計和檢索。
因為伴魚的慢日志系統(tǒng)做得比較早，所以采用的是 ELK 的架構(gòu)。
首先，F(xiàn)ilebeat 足夠輕量。我們在線上對幾百兆文件做過解析測試，結(jié)論是對數(shù)據(jù)庫的性能基本上沒有影響。
其次，當(dāng)線上出現(xiàn)問題時，瞬時的日志量是特別大的，如果把慢日志直接寫入到 Logstash，會對 Logstash 機(jī)器負(fù)載造成沖擊，所以通過 Kafka 來消峰。
當(dāng) Logstash 解析慢日志的時候，應(yīng)盡量少用模糊匹配的規(guī)則。因為用模糊匹配的規(guī)則去解析慢日志，會導(dǎo)致機(jī)器 CPU 飆高的問題。
然后，ES 索引本身就是 Schema Free 的，然后加上倒排索引這種數(shù)據(jù)結(jié)構(gòu)，這種特性非常適合統(tǒng)計分析類場景。
同時，通過 Kibana 做可視化檢索和統(tǒng)計分析。
最后，我們每 2 分鐘讀取一次 ES 的慢日志數(shù)據(jù)，做監(jiān)控報警。
日志采集
接下來看一下每個組件的細(xì)節(jié)，左邊是 Filebeat 采集的配置，如下圖所示。我們在部署 Filebeat 的時候，會把部署機(jī)器的 IP 給傳進(jìn)去，這樣在后期統(tǒng)計的時候，就知道慢日志是來源于哪臺機(jī)器。然后右邊是 Kafka 的配置，數(shù)據(jù)收集好之后，會發(fā)送到 Kafka 集群。
下面是一條 TiDB 慢日志的示例，格式是這樣的。
字段篩選
一條文本沒法做統(tǒng)計分析和多維檢索的，如果我們要做，就需要把這行文本里面的字段解析出來，那么我們關(guān)注哪些字段呢？首先來看一下 MySQL 5.7 的慢日志，如下圖所示。我們在處理 MySQL 故障的時候，首先會看一條 SQL 的查詢時間，如果該 SQL 查詢時間比較長，我們認(rèn)為它可能會是導(dǎo)致線上問題的原因。
但是當(dāng)線上請求量比較大的時候，查詢時間長并不能代表它就是引發(fā)問題的根本原因，還要結(jié)合其它關(guān)鍵字段來綜合分析。比如慢日志里一個特別重要的關(guān)鍵字 Rows_examined，Rows_examined 代表了數(shù)據(jù)邏輯掃描的行數(shù)，通常我們通過 Query_time 和 Rows_examined 綜合分析，才可以定位問題 SQL。
接下來，我們看一下 TiDB 的慢日志。首先來看一下 TiDB 3.0.13 走 KV 接口的慢日志，如下圖所示。這里有一些比較重要的關(guān)鍵字，比如說 Query_time，DB，SQL 和 Prewrite_time，這些關(guān)鍵字對于定位線上問題是很有幫助的。
下面是另外一種格式的 TiDB 3.0.13 的慢日志，它是走 DistSQL 接口的，如下圖所示。
它除了把 Query_time、Total_keys 同時打印出來之后，還有 Index_names，代表這條 SQL 有沒有走索引，同時 Index_names 字段里面還有表名等信息。
看完了 TiDB 3.0.13 的慢日志，我們再來看一下 TiDB 4.0.13 的慢日志，慢日志內(nèi)容相比 TiDB 3.0.13 版本又增加了一些字段，比如 KV_total，PD_total，Backoff_total 等信息。
通過上面的慢日志，我們可以發(fā)現(xiàn)其中包含了很多關(guān)鍵信息，我們甚至可以看到請求慢在數(shù)據(jù)庫的哪個環(huán)節(jié)。如果我們把慢日志收集起來，通過某些關(guān)系進(jìn)行檢索，甚至聚合，對于發(fā)現(xiàn)問題是很有幫助的。
TiDB IP：在部署 Filebeat 的時候，會把機(jī)器的 IP 給傳進(jìn)去。有了這個 IP，我們可以知道日志的來源以及按照 IP 的維度進(jìn)行統(tǒng)計；
DB：執(zhí)行語句時使用的 DATABASE。我們可以按照 DB 維度進(jìn)行統(tǒng)計，同時也可以通過內(nèi)部系統(tǒng)將 DB 和具體的數(shù)據(jù)庫集群映射起來；
TABLE：有些慢日志是可以解析出表名的，可按照表的維度進(jìn)行統(tǒng)計；
IDX_NAME：除 Insert 語句 和走 KV 接口的語句外，慢日志信息記錄了語句有沒有走索引；
TOTAL_KEYS：Coprocessor 掃過的 Key 的數(shù)量；
PROCESS_KEYS：Coprocessor 處理的 Key 的數(shù)量；
QUERY_TIME：語句執(zhí)行的時間；
SQL：具體的 SQL 語句。
字段解析
統(tǒng)計分析
下面這個圖是我們所有集群在最近 30 分鐘之內(nèi)的慢日志情況。我們通過 Kibana，可以看到慢日志的總條數(shù)，可以通過 DB、Quwry_time、Total_keys 來進(jìn)行檢索，還可以按 DB、Table、IP 等維度進(jìn)行統(tǒng)計。這樣能夠極大地提高定位問題 SQL 的效率。
監(jiān)控告警
但是我們發(fā)現(xiàn)線上也存在執(zhí)行頻率特別低，但是執(zhí)行時間特別長的情況，就沒辦法通過通用的規(guī)則去覆蓋。所以后面又加了一條規(guī)則：執(zhí)行時間超過 500 毫秒，告警閥值達(dá)到 2 條就告警。這樣對于線上的慢 SQL 就基本上全覆蓋了。
案例分享
講完了慢日志系統(tǒng)是怎么做的，接下來看一下我們是如何通過慢日志系統(tǒng)去發(fā)現(xiàn)線上問題。
第一個案例，如下圖所示。我們在某天發(fā)現(xiàn)集群的 Coprocessor CPU 上去了，同時對應(yīng)著右邊的延時也上去了，通過慢日志系統(tǒng)很快就能發(fā)現(xiàn)問題 SQL，它的 Total_keys 和 Process_keys 耗得比較多，另外它的 index_name 是空的，說明它沒有走到索引。我們通過給這條 SQL 加上索引，性能問題就快速地解決了。
總結(jié)
