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應該是執行結果的一個反饋。