转载

MyCAT日志分析

MyCAT日志对于了解MyCAT的运行信息不可获取,譬如MyCAT是否采用读写分离,对于一个查询语句,MyCAT是怎样执行的,每个分片会分发到哪个节点上等等。

默认是info级别,通过log4j.xml可将其设置debug级别,这样就可获得更多有关MyCAT运行的内部信息。

下面通过对MyCAT的启动以及执行一个查询语句来分析MyCAT的运行流程。

Here We Go!

Mycat的启动 日志输入如下:

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。

MyCAT日志分析

创建完毕后,会输出如下信息,代表连接创建完毕

MyCAT日志分析

执行心跳检测 ,所以需建立新的连接,因为我配置的是一主两从,所以需判断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的输出信息 ,可以看出,连接到MyCAT后,会执行show database,show tables,select @@version_comment limit 1命令。个人感觉这是为后续的路由分析缓存数据库及表信息。

MyCAT日志分析

接下来执行一下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:会存在数据的合并

MyCAT日志分析

下面就可以 确认具体在哪个节点去读了

因为我配置的是一主两从,且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,需修改。

MyCAT日志分析

对于每一个同步的连接,需在连接同步后才开始执行查询。

一共有5个received ok response,其中2个对应上图中的total syn cmd 2 commands,另外3个对应于上图中的total syn cmd 3 commands,根据host也能很轻易的对应起来。

MyCAT日志分析

下面开始执行程序,

第一个红色方框针对的是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的结果的输出。

MyCAT日志分析

下面是dn2分片的输出,因为dn2分片是刚才新建的连接,所以同样需要同步,收到两次received ok response后,返回结果,然后释放connection和channel。

最后是DataMergeService合并所有返回的结果。

last packet id预计是MyCAT将结果反馈给前段程序。

至此,一个查询语句的日志分析完毕~

MyCAT日志分析

总结:

1. 其实同步连接的时候,并不必然会产生received ok response信息,譬如我在执行SELECT * FROM travelrecord WHERE id = 1语句时,

在执行同步连接后,就直接释放了connection和channel,并没有产生received ok response信息,也没有产生on row end reseponse。

看来,这个只能通过源码才能知晓个中原因。

MyCAT日志分析

2. 平时分析MyCAT日志,一般会使用tailf命令,但频繁的心跳检测信息又确实是个干扰,可通过 tailf mycat.log |grep -Ev "Timer|release channel"过滤掉部分信息。

原文  http://www.cnblogs.com/ivictor/p/5150269.html
正文到此结束
Loading...