Mycat学习笔记第四篇. MyCat 日志简单分析

环境说明

Windows 7 Mycat 1.5 Mysql 5.5 一个实例两个库 traveldata_db_1 和 traveldata_db_2

Mycat 服务启动，初始化各项数据参数

01/22 15:54:33.041 INFO [WrapperSimpleAppMain] (MycatServer.java:197) -===============================================
01/22 15:54:33.041 INFO [WrapperSimpleAppMain] (MycatServer.java:198) -MyCat is ready to startup ...
01/22 15:54:33.041 INFO [WrapperSimpleAppMain] (MycatServer.java:208) -Startup processors ...,total processors:2,aio thread pool size:4
each process allocated socket buffer pool bytes ,buffer chunk size:4096 buffer pool's capacity(buferPool/bufferChunk) is:2000
01/22 15:54:33.041 INFO [WrapperSimpleAppMain] (MycatServer.java:209) -sysconfig params:SystemConfig [processorBufferLocalPercent=100, frontSocketSoRcvbuf=1048576, frontSocketSoSndbuf=4194304, backSocketSoRcvbuf=4194304, backSocketSoSndbuf=1048576, frontSocketNoDelay=1, backSocketNoDelay=1, maxStringLiteralLength=65535, frontWriteQueueSize=2048, bindIp=0.0.0.0, serverPort=8066, managerPort=9066, charset=utf8, processors=2, processorExecutor=4, timerExecutor=2, managerExecutor=2, idleTimeout=1800000, catletClassCheckSeconds=60, sqlExecuteTimeout=300, processorCheckPeriod=1000, dataNodeIdleCheckPeriod=300000, dataNodeHeartbeatPeriod=10000, clusterHeartbeatUser=_HEARTBEAT_USER_, clusterHeartbeatPass=_HEARTBEAT_PASS_, clusterHeartbeatPeriod=5000, clusterHeartbeatTimeout=10000, clusterHeartbeatRetry=10, txIsolation=3, parserCommentVersion=50148, sqlRecordCount=10, processorBufferPool=8192000, processorBufferChunk=4096, defaultMaxLimit=100, sequnceHandlerType=0, sqlInterceptor=org.opencloudb.interceptor.impl.DefaultSqlInterceptor, sqlInterceptorType=select, sqlInterceptorFile=D:inmycatmycat1.5/logs/sql.txt, mutiNodeLimitType=0, mutiNodePatchSize=100, defaultSqlParser=druidparser, usingAIO=0, packetHeaderSize=4, maxPacketSize=16777216, mycatNodeId=1]
01/22 15:54:33.062 INFO [WrapperSimpleAppMain] (MycatServer.java:268) -using nio network handler
01/22 15:54:33.089 INFO [WrapperSimpleAppMain] (MycatServer.java:286) -$_MyCatManager is started and listening on 9066
01/22 15:54:33.090 INFO [WrapperSimpleAppMain] (MycatServer.java:290) -$_MyCatServer is started and listening on 8066
01/22 15:54:33.090 INFO [WrapperSimpleAppMain] (MycatServer.java:292) -===============================================

01/22 15:54:33.090 INFO [WrapperSimpleAppMain] (MycatServer.java:295) -Initialize dataHost ...

分别在物理库上建立数据库连接
01/22 15:54:33.090 INFO [WrapperSimpleAppMain] (PhysicalDBPool.java:294) -init backend myqsl source ,create connections total 10 for hostM1 index :0
01/22 15:54:33.091 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_1
01/22 15:54:33.092 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_2
01/22 15:54:33.093 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_1
01/22 15:54:33.093 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_2
01/22 15:54:33.093 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_1
01/22 15:54:33.093 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_2
01/22 15:54:33.096 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_1
01/22 15:54:33.096 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_2
01/22 15:54:33.096 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_1
01/22 15:54:33.096 INFO [WrapperSimpleAppMain] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema traveldata_db_2

看上去像是连接成功

01/22 15:54:33.127 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection [id=8, lastTime=1453449273127, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=291, charset=utf8, txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

01/22 15:54:33.127 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection [id=7, lastTime=1453449273127, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=294, charset=utf8, txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

主动断开数据库连接
01/22 15:54:33.127 DEBUG [$_NIOREACTOR-0-RW] (PhysicalDatasource.java:403) -release channel MySQLConnection [id=8, lastTime=1453449273127, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=291, charset=utf8, txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
01/22 15:54:33.127 DEBUG [$_NIOREACTOR-1-RW] (PhysicalDatasource.java:403) -release channel MySQLConnection [id=7, lastTime=1453449273127, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=294, charset=utf8, txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

DML语句执行分析

01/22 16:26:14.058 DEBUG [$_NIOREACTOR-1-RW] (ServerQueryHandler.java:56) -ServerConnection [id=1, schema=TRDB, host=0:0:0:0:0:0:0:1, user=test,txIsolation=3, autocommit=true, schema=TRDB]select * from t_vote

没有加入查询条件，即不命中Cache，分析出来需要执行2次查询并进行数据拼装
01/22 16:26:14.059 DEBUG [$_NIOREACTOR-1-RW] (EnchachePool.java:70) -SQLRouteCache hit cache ,key:TRDBselect * from t_vote
01/22 16:26:14.059 DEBUG [$_NIOREACTOR-1-RW] (NonBlockingSession.java:113) -ServerConnection [id=1, schema=TRDB, host=0:0:0:0:0:0:0:1, user=test,txIsolation=3, autocommit=true, schema=TRDB]select * from t_vote, route={
1 -> dn1{SELECT *
FROM t_vote
LIMIT 100}
2 -> dn3{SELECT *
FROM t_vote
LIMIT 100}
} rrs
01/22 16:26:14.059 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:82) -execute mutinode query select * from t_vote
01/22 16:26:14.060 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:97) -has data merge logic
01/22 16:26:14.060 DEBUG [$_NIOREACTOR-1-RW] (PhysicalDBPool.java:452) -select read source hostM1 for dataHost:localhost1
01/22 16:26:14.060 DEBUG [$_NIOREACTOR-1-RW] (MySQLConnection.java:445) -con need syn ,total syn cmd 1 commands SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false con:MySQLConnection [id=28, lastTime=1453451174060, user=root, schema=traveldata_db_1, old shema=traveldata_db_1, borrowed=true, fromSlaveDB=false, threadId=313, charset=utf8, txIsolation=0, autocommit=true, attachment=dn1{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

发起Mysql查询请求
01/22 16:26:14.061 DEBUG [$_NIOREACTOR-1-RW] (PhysicalDBPool.java:452) -select read source hostM1 for dataHost:localhost1
01/22 16:26:14.061 DEBUG [$_NIOREACTOR-1-RW] (MySQLConnection.java:445) -con need syn ,total syn cmd 1 commands SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false con:MySQLConnection [id=33, lastTime=1453451174061, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=318, charset=utf8, txIsolation=0, autocommit=true, attachment=dn3{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

得到响应结果
01/22 16:26:14.061 DEBUG [$_NIOREACTOR-0-RW] (MultiNodeQueryHandler.java:171) -received ok response ,executeResponse:false from MySQLConnection [id=28, lastTime=1453451174048, user=root, schema=traveldata_db_1, old shema=traveldata_db_1, borrowed=true, fromSlaveDB=false, threadId=313, charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@a746115, writeQueue=0, modifiedSQLExecuted=false]
01/22 16:26:14.062 DEBUG [$_NIOREACTOR-0-RW] (DataMergeService.java:94) -field metadata inf:[DATA=ColMeta [colIndex=2, colType=253], VID=ColMeta [colIndex=0, colType=3], PROVINCE=ColMeta [colIndex=1, colType=3]]
01/22 16:26:14.062 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:171) -received ok response ,executeResponse:false from MySQLConnection [id=33, lastTime=1453451174048, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=318, charset=utf8, txIsolation=3, autocommit=true, attachment=dn3{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@2e7c324a, writeQueue=0, modifiedSQLExecuted=false]

这步开始应该开始做数据整合
01/22 16:26:14.062 DEBUG [$_NIOREACTOR-0-RW] (MultiNodeQueryHandler.java:241) -on row end reseponse MySQLConnection [id=28, lastTime=1453451174048, user=root, schema=traveldata_db_1, old shema=traveldata_db_1, borrowed=true, fromSlaveDB=false, threadId=313, charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@a746115, writeQueue=0, modifiedSQLExecuted=false]
01/22 16:26:14.062 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:241) -on row end reseponse MySQLConnection [id=33, lastTime=1453451174048, user=root, schema=traveldata_db_2, old shema=traveldata_db_2, borrowed=true, fromSlaveDB=false, threadId=318, charset=utf8, txIsolation=3, autocommit=true, attachment=dn3{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@2e7c324a, writeQueue=0, modifiedSQLExecuted=false]

释放数据库连接
01/22 16:26:14.063 DEBUG [$_NIOREACTOR-0-RW] (NonBlockingSession.java:229) -release connection MySQLConnection [id=28, lastTime=1453451174048, user=root, schema=traveldata_db_1, old shema=traveldata_db_1, borrowed=true, fromSlaveDB=false, threadId=313, charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SELECT *
FROM t_vote
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@33c40638, host=localhost, port=3308, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@a746115, writeQueue=0, modifiedSQLExecuted=false]

OK，整个查询的日志基本如此。

Mycat学习笔记 第四篇. MyCat 日志简单分析

Mycat学习笔记第四篇. MyCat 日志简单分析