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应该是执行结果的一个反馈。