MyCAT日誌分析

MyCAT日誌分析

MyCAT日誌對於瞭解MyCAT的運行資訊不可擷取，譬如MyCAT是否採用讀寫分離，對於一個查詢語句，MyCAT是怎樣執行的，每個分區會分發到哪個節點上等等。

預設是info層級，通過log4j.xml可將其設定debug層級，這樣就可獲得更多有關MyCAT啟動並執行內部資訊。

下面通過對MyCAT的啟動以及執行一個查詢語句來分析MyCAT的運行流程。

Here We Go!

Mycat的開機記錄輸入如下：

processors指的是CPU的核心數，aio thread pool size指的是AIO線程池，為CPU核心數的兩倍

-sysconfig params：指的是mycat的啟動參數，可在server.xml中修改。

其中idleTimeout=1800000指的是外部應用與mycat最大空閑串連時間長度為30min，超過30min，則外部應用到mycat的串連將被斷開。

      dataNodeHeartbeatPeriod=10000 節點心跳檢測的頻率為10s一次。

9066是MyCAT的管理連接埠

8066是MyCAT的預設連接埠，類似於MySQL的3306連接埠。

接下來初始化MyCAT串連池，預設最小為10個串連

可通過schema.xml中dataHost處定義

-init backend myqsl source ,create connections total 10 for hostM1 index :0：初始化後端MySQL串連，master節點是hostM1，可根據conf目錄下dnindex.properties檔案指定。

再下面的輸出資訊就是建立串連，釋放channel。

建立完畢後，會輸出如下資訊，代表串連建立完畢

執行心跳檢測，所以需建立新的串連，因為我配置的是一主兩從，所以需判斷localhost，192.168.244.144和192.168.244.146的心跳，localhost已啟動10個串連，所以不需要建立新的串連，但hostS1（即192.168.244.146）和hostS2（即192.168.244.144）需要。

threadID對應的是MySQL中的進程ID

接下來是前端串連到MyCAT的輸出資訊，可以看出，串連到MyCAT後，會執行show database，show tables，select @@version_comment limit 1命令。個人感覺這是為後續的路由分析快取資料庫及表資訊。

接下來執行一下select * from travelrecord，查看MyCAT的內部實現邏輯

首先會判斷該SQL語句的路由資訊（根據下面的輸出，MyCAT內部應該用了一個map集合來儲存SQL語句的路由資訊），如果沒有，則會首先產生路由資訊。

路由的主要作用是用於確定SQL語句的執行路徑，包括查詢的資料在哪些分區上。

-SQLRouteCache  miss cache：沒有路由資訊

-SQLRouteCache add cache：產生路由資訊

-execute mutinode query select * from travelrecord：確認該查詢會跨多個分區

-has data merge logic：會存在資料的合并

下面就可以確認具體在哪個節點去讀了

因為我配置的是一主兩從，且balance="1"，全部的readHost與stand by writeHost參與select語句的負載平衡，所以hostS1（192.168.244.146）和hostS2（192.168.244.144）均參與select語句的負載平衡。

在執行select語句之前，需同步串連，為什麼要同步串連呢？

MyCAT為了高效的使用後端的MySQL串連，採用了基於MySQL執行個體的串連池模式。

在Mycat的串連池裡，當前可用的MySQL串連是放到一個HashMap的資料結構裡，Key為當前串連對應的Database，另外還有二級分類，即按照串連是自動認可還是手動提交模式進行區分，這個設計是為了高效的查詢匹配的可用串連，具體邏輯如下：

當某個使用者會話需要一個自動認可的，到分區dn1(對應db1）的SQL串連的時候，串連池首先找是否有db1上的可用串連，如果有，看是否有自動認可模式的串連，找到就返回，否則返回db1上的手動提交模式的串連，若沒有db1的可用串連，則隨機返回一個其他db對應的可用串連，若沒有可用串連，並且串連池還沒達到上限，則建立一個新串連並返回，這個邏輯過程，我們會發現，使用者會話得到的串連可能不是他原先想要的，比如Database不對應，或者事務模式不匹配，因此在執行具體的SQL之前，還有一個自動同步資料庫連接的過程，包括交易隔離等級、事務模式、字元集、Database等四個指標，同步完成以後，才會執行具體的SQL指令。

在執行select * from travelrecord語句時，因為會涉及到3個分區，故MyCAT選擇了三個read source進行查詢，其中，兩個在hostS2上，一個在hostS1上。對於hostS2的兩個串連，其中一個會複用MyCAT之前對hostS2執行心跳檢測的串連，另一個需建立。

對於hostS2複用之前的串連，因為之前執行心跳檢測的時候即使用的db1，所以這次schema change為false，不用修改。

而對於hostS1複用之前的串連，因為之前使用的是db1，這次是db3，所以schema change為true，需修改。

對於每一個同步的串連，需在串連同步後才開始執行查詢。

一共有5個received ok response，其中2個對應中的total syn cmd 2 commands，另外3個對應於中的total syn cmd 3 commands，根據host也能很輕易的對應起來。

下面開始執行程式，

第一個紅色方框針對的是192.168.244.146中dn3分區上，因為我整個select * from travelrecord輸出只有兩行，

mysql> select * from travelrecord;+---------+---------------+------------+------+------+| id      | user_id       | traveldate | fee  | days |+---------+---------------+------------+------+------+|       1 | mysql-server2 | 2016-01-01 |  100 |   10 || 5000001 | mysql-server3 | 2016-01-02 |  100 |   10 |+---------+---------------+------------+------+------+2 rows in set (0.04 sec)

只跨兩個分區，dn1和dn2，所以dn3的查詢沒有結果輸出，直接釋放connection和channel。

藍色方框和第二個紅色方框的內容是有關192.168.244.144中dn1的，有結果輸出。

-field metadata inf: DataMergeService先合并了輸出資料行的資訊。

 -on row end reseponse：代表dn1的結果的輸出。

下面是dn2分區的輸出，因為dn2分區是剛才建立的串連，所以同樣需要同步，收到兩次received ok response後，返回結果，然後釋放connection和channel。

最後是DataMergeService合并所有返回的結果。

last packet id預計是MyCAT將結果反饋給前段程式。

至此，一個查詢語句的日誌分析完畢~

總結：

1. 其實同步串連的時候，並不必然會產生received ok response資訊，譬如我在執行SELECT * FROM travelrecord WHERE id = 1語句時，

在執行同步串連後，就直接釋放了connection和channel，並沒有產生received ok response資訊，也沒有產生on row end reseponse。

看來，這個只能通過源碼才能知曉箇中原因。

2. 平時分析MyCAT日誌，一般會使用tailf命令，但頻繁的心跳檢測資訊又確實是個幹擾，可通過 tailf mycat.log |grep -Ev "Timer|release channel"過濾掉部分資訊。

3. received ok response並不只是針對串連同步的，在執行drop table操作時也會產生。

所以，received ok response應該是執行結果的一個反饋。

本文永久更新連結地址：