5，Mycat日志分析

mycat 的日志文件配置为MYCAT_HOME/conf/log4j.xml,结构为：

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

<appender name="ConsoleAppender" class="org.apache.log4j.ConsoleAppender">

<layout class="org.apache.log4j.PatternLayout">

<param name="ConversionPattern" value="%d{MM-dd HH:mm:ss.SSS} %5p [%t] (%F:%L) -%m%n" />

</layout>

</appender>

<appender name="FILE" class="org.apache.log4j.RollingFileAppender">

<param name="file" value="${MYCAT_HOME}/logs/mycat.log" />

<param name="Append" value="false"/>

<param name="MaxFileSize" value="10000KB"/>

<param name="MaxBackupIndex" value="10"/>

<param name="encoding" value="UTF-8" />

<layout class="org.apache.log4j.PatternLayout">

<param name="ConversionPattern" value="%d{MM/dd HH:mm:ss.SSS} %5p [%t] (%F:%L) -%m%n" />

</layout>

</appender>

<root>

<level value="debug" />

<appender-ref ref="ConsoleAppender" />

</root>

</log4j:configuration>

 

日志配置是标准的log4j 配置，其中：

<param name="file" value="${MYCAT_HOME}/logs/mycat.log" />

是日志文件的存放目录。

<root>

<level value="debug" />

<appender-ref ref="ConsoleAppender" />

</root>

是日志的级别，生产环境下建议将级别调整为info/ware,如果是开发测试，特别是碰到异常可以通过开启debug 模式观察日志的信息查找异常原因。

 

warpper 日志

目前Mycat 的启动是经过warapper 封装成启动脚本，所以日志也会有其相关的日志文件：

${MYCAT_HOME}/logs/warapper.log,再启动时候如果系统环境配置错误或缺少配置时，导致Mycat 无法启动，可以通过查看warrpper.log 查看具体错误原因。

 

mycat 日志

 

debug 模式下分析sql 执行

下面分析sql：select * from t_user t; 的执行

04-29 22:06:10.187 INFO [$_NIOREACTOR-3-RW] (FrontendAuthenticator.java:161) -ServerConnection [id=1,schema=null, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=null]'mycat' login success

04-29 22:06:10.188 DEBUG [$_NIOREACTOR-3-RW] (ServerQueryHandler.java:64) -ServerConnection [id=1,schema=null, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=null]SET NAMES utf8

04-29 22:06:10.192 DEBUG [$_NIOREACTOR-3-RW] (ServerQueryHandler.java:64) -ServerConnection [id=1,schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]SHOW STATUS

04-29 22:06:10.227 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:118) -ServerConnection [id=1,

schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]SHOW STATUS,

route={

1 -> dn2{SHOW STATUS}

} rrs

04-29 22:06:10.228 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for

dataHost:jdbchost2

04-29 22:06:10.228 DEBUG [$_NIOREACTOR-3-RW] (MySQLConnection.java:437) -con need syn ,total syn

cmd 1 commands SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false

con:MySQLConnection [id=13, lastTime=1430316370226, schema=mycat_node1, old shema=mycat_node1,

borrowed=true, fromSlaveDB=false, threadId=17188, charset=utf8, txIsolation=0, autocommit=true,

attachment=dn2{SHOW STATUS}, respHandler=SingleNodeHandler [node=dn2{SHOW STATUS},

packetId=0], host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

04-29 22:06:10.313 DEBUG [$_NIOREACTOR-3-RW] (ServerQueryHandler.java:64) -ServerConnection [id=1,

schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]select * from

t_user t

04-29 22:06:10.315 DEBUG [$_NIOREACTOR-3-RW] (EnchachePool.java:76) -SQLRouteCache miss

cache ,key:mycatselect * from t_user t

04-29 22:06:10.419 DEBUG [$_NIOREACTOR-3-RW] (EnchachePool.java:59) -SQLRouteCache add

cache ,key:mycatselect * from t_user t value:select * from t_user t, route={

1 -> dn1{SELECT *

FROM t_user t

LIMIT 100}

2 -> dn2{SELECT *

FROM t_user t

LIMIT 100}

04-29 22:06:10.420 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:118) -ServerConnection [id=1,

schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]select * fromt_user t, route={

1 -> dn1{SELECT *

FROM t_user t

LIMIT 100}

2 -> dn2{SELECT *

FROM t_user t

LIMIT 100}

} rrs

04-29 22:06:10.420 DEBUG [$_NIOREACTOR-3-RW] (MultiNodeQueryHandler.java:78) -execute mutinode

query select * from t_user t

04-29 22:06:10.422 DEBUG [$_NIOREACTOR-3-RW] (MultiNodeQueryHandler.java:93) -has data merge logic

04-29 22:06:10.422 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for dataHost:jdbchost

04-29 22:06:10.422 DEBUG [$_NIOREACTOR-3-RW] (MySQLConnection.java:437) -con need syn ,total syn

cmd 1 commands SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false

con:MySQLConnection [id=1, lastTime=1430316370409, schema=mycat_node1, old shema=mycat_node1,

borrowed=true, fromSlaveDB=false, threadId=89067, charset=utf8, txIsolation=0, autocommit=true,

attachment=dn1{SELECT *

FROM t_user t

LIMIT 100}, respHandler=io.mycat.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,

host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

04-29 22:06:10.423 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for dataHost:jdbchost2

04-29 22:06:10.423 DEBUG [$_NIOREACTOR-3-RW] (MySQLConnection.java:437) -con need syn ,total syn

cmd 1 commands SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false

con:MySQLConnection [id=11, lastTime=1430316370409, schema=mycat_node1, old shema=mycat_node1,borrowed=true, fromSlaveDB=false, threadId=17189, charset=utf8, txIsolation=0, autocommit=true,attachment=dn2{SELECT * FROM t_user t LIMIT 100}, respHandler=io.mycat.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,

host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]

04-29 22:06:10.432 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:165) -received ok

response ,executeResponse:false from MySQLConnection [id=1, lastTime=1430316370409,

schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false, threadId=89067,

charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SELECT *

FROM t_user t

LIMIT 100}, respHandler=io.mycat.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,

host=121.40.121.133, port=3306, statusSync=io.mycat.mysql.nio.MySQLConnection$StatusSync@7485fef2,

writeQueue=0, modifiedSQLExecuted=false]

04-29 22:06:10.434 DEBUG [$_NIOREACTOR-1-RW] (DataMergeService.java:138) -field metadata

inf:[RECEIVE_ADDRESS=ColMeta [colIndex=1, colType=253],

通过该日志可以看到Mycat 整个执行的计划。

其中最重要的是sql 路由的计划，可以看到sql 具体被分配到那个分片执行：

04-29 22:06:10.420 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:118) -ServerConnection [id=1,

schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]select * from

t_user t, route={

1 -> dn1{SELECT *

FROM t_user t

LIMIT 100}

2 -> dn2{SELECT *

FROM t_user t

LIMIT 100}

} rrs

04-29 22:06:10.420 DEBUG [$_NIOREACTOR-3-RW] (MultiNodeQueryHandler.java:78) -execute mutinode

query select * from t_user t

该部分描述了该条sql 被分配到到了分片dn1、dn2 上同时执行，如果某个某个sql 通过缓存、分片规则或

者注解指定只会在某个分片执行，则sql 只会被分配到到某个分片，例如：

sql=select * from t_user t where t.user_id=121;该条数据只在分片1 上。

04-29 22:13:40.960 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:118) -ServerConnection [id=1,

schema=mycat, host=127.0.0.1, user=mycat,txIsolation=3, autocommit=true, schema=mycat]select * from

t_user t where t.user_id=121, route={

1 -> dn1{SELECT *

FROM t_user t

WHERE t.user_id = 121

LIMIT 100}

} rrs

从日志可以看出sql 只被路由到dn1 节点执行。

 

异常日志