MyCat:第五章:快速入门
快速入门
10分钟入门
MyCAT是使用JAVA语言进行编写开发,使用前需要先安装JAVA运行环境(JRE),由于MyCAT中使用了JDK7中的一些特性,所以
要求必须在JDK7以上的版本上运行。
1.环境准备
1) JDK下载
http://www.oracle.com/technetwork/java/javase/downloads/jdk7-downloads-1880260.html
注:必须JDK7或更高版本.
2) MySQL下载
http://dev.mysql.com/downloads/mysql/5.5.html#downloads
注:MyCAT支持多种数据库接入,如:MySQL、SQLServer、Oracle、MongoDB等,推荐使用MySQL做集群。
3) MyCAT项目主页
https://github.com/MyCATApache/
注:MyCAT相关源码、文档都可以在此地址下进行下载。
2.环境安装与配置
如果是第一次刚接触MyCAT,建议先下载MyCAT-Server源码到本地,通过Eclipse等工具进行配置和运行,便于深入了解和调
试程序运行逻辑。
1) MyCAT-Server源码下载
由于MyCAT源码目前主要托管在github上,需要先在本地安装和配置好相关环境,具体参考群共享中“github-eclipse开发指
南.docx”,这说明有很详细的配置说明,按照文档中的步骤把MyCAT-Server源码下载到本地即可。
MyCAT-Server仓库地址:https://github.com/MyCATApache/Mycat-Server.git
2) 源码调试与配置
MyCAT目前主要通过配置文件的方式来定义逻辑库和相关配置:
• MYCAT_HOME/conf/schema.xml中定义逻辑库,表、分片节点等内容.
• MYCAT_HOME/conf/rule.xml中定义分片规则.
• MYCAT_HOME/conf/server.xml中定义用户以及系统相关变量,如端口等.
注:以上几个文件的具体配置请参考前面章节中的具体说明.
3) 源码运行
MyCAT入口程序是org.opencloudb.MycatStartup.java,右键run as出现下面的界面,需要设置MYCAT_HOME目录,为你工
程当前所在目录(src/main):
设置完MYCAT主目录后即可正常运行MyCAT服务。
注:若启动报错,DirectBuffer内存不够,则可以再加JVM系统参数:
XX:MaxDirectMemorySize=128M
3.快速镜像方式体验MyCAT
此方式通过将已经安装和配置好的MySQL+MyCAT做成镜像,可实现快速运行和体验MyCAT服务。
镜像文件及快速运行体验文档下载地址:
http://pan.baidu.com/s/1o61EXaa
2.2 服务安装与配置
linux
MyCAT有提供编译好的安装包,支持windows、Linux、Mac、Solaris等系统上安装与运行。
linux下可以下载Mycat-server-xxxxx.linux.tar.gz 解压在某个目录下,注意目录不能有空格,在Linux(Unix)下,建议放在
usr/local/Mycat目录下,如下:
下面是修改MyCAT用户密码的方式(仅供参考):
目录解释如下:
bin 程序目录,存放了window版本和linux版本,除了提供封装成服务的版本之外,也提供了nowrap的shell脚本命令,方便大
家选择和修改,进入到bin目录:
•Linux下运行:./mycat console,首先要chmod +x *
注:mycat支持的命令{ console | start | stop | restart | status | dump }
conf目录下存放配置文件,server.xml是Mycat服务器参数调整和用户授权的配置文件,schema.xml是逻辑库定义和表以及分片
定义的配置文件,rule.xml是分片规则的配置文件,分片规则的具体一些参数信息单独存放为文件,也在这个目录下,配置文件
修改,需要重启Mycat或者通过9066端口reload.
lib目录下主要存放mycat依赖的一些jar文件.
日志存放在logs/mycat.log中,每天一个文件,日志的配置是在conf/log4j.xml中,根据自己的需要,可以调整输出级别为
debug,debug级别下,会输出更多的信息,方便排查问题.
注意:Linux下部署安装MySQL,默认不忽略表名大小写,需要手动到/etc/my.cnf 下配置 lower_case_table_names=1 使
Linux环境下MySQL忽略表名大小写,否则使用MyCAT的时候会提示找不到表的错误!
windows
MyCAT有提供编译好的安装包,支持windows、Linux、Mac、Solaris等系统上安装与运行。
windows下可以下载Mycat-server-xxxxx-win.tar.gz 解压在某个目录下,建议解压到本地某个盘符根目录下,如下:
目录解释如下:
bin 程序目录,存放了window版本和linux版本,除了提供封装成服务的版本之外,也提供了nowrap的shell脚本命令,方便大
家选择和修改,进入到bin目录:
•Windows下运行:运行: mycat.bat console 在控制台启动程序,也可以装载成服务,若此程序运行有问题,也可以运行
startup_nowrap.bat,确保java命令可以在命令执行.
•Windows下将MyCAT做成系统服务:MyCAT提供warp方式的命令,可以将MyCAT安装成系统服务并可启动和停止。
1) 进入bin目录下执行命令 mycat install 执行安装mycat服务.
2) 输入 mycat start 启动mycat服务.
conf目录下存放配置文件,server.xml是Mycat服务器参数调整和用户授权的配置文件,schema.xml是逻辑库定义和表以及分片
定义的配置文件,rule.xml是分片规则的配置文件,分片规则的具体一些参数信息单独存放为文件,也在这个目录下,配置文件
修改,需要重启Mycat或者通过9066端口reload.
lib目录下主要存放mycat依赖的一些jar文件.
日志存放在logs/mycat.log中,每天一个文件,日志的配置是在conf/log4j.xml中,根据自己的需要,可以调整输出级别为
debug,debug级别下,会输出更多的信息,方便排查问题.
2.3 服务启动与启动设置
linux
1.MyCAT在Linux中部署启动时,首先需要在Linux系统的环境变量中配置MYCAT_HOME,操作方式如下:
1) vi /etc/profile,在系统环境变量文件中增加 MYCAT_HOME=/usr/local/Mycat
2) 执行 source /etc/profile 命令,使环境变量生效。
如果是在多台Linux系统中组建的MyCAT集群,那需要在MyCAT Server所在的服务器上配置对其他ip和主机名的映射,
配置方式如下:
1) vi /etc/hosts
例如:我有4台机器,配置如下:
IP 主机名
192.168.100.2 sam_server_1
1.
192.168.100.3 sam_server_2
192.168.100.4 sam_server_3
192.168.100.5 sam_server_4
编辑完后,保存文件。
经过以上两个步骤的配置,就可以到/usr/local/Mycat/bin 目录下执行:
./mycat start
即可启动mycat服务!
windows
MyCAT在windows中部署时,建议放在某个盘符的根目录下,如果不是在根目录下,请尽量不要放在包含中文的目录下
如:D:\Mycat-server-1.4-win\
命令行方式启动:
从cmd中执行命令到达 D:\Mycat-server-1.4-win\bin 目录下,执行startup_nowrap.bat 即可启动MyCAT服务。
注:执行此命令时,需要确保windows系统中已经配置好了JAVA的环境变量,并可执行java命令。jdk版本必须是1.7及以上版
本。
服务方式启动:
从cmd中执行命令到达 D:\Mycat-server-1.4-win\bin 目录下,执行:
mycat install //表示执行安装MyCAT服务
mycat remove //表示执行卸载MyCAT服务
服务安装完后,就可以通过windows系统服务对MyCAT进行启动和停止了。
2.4 demo使用
1) springMVC+ibatis+FreeMarker 连接mycat示例:
http://pan.baidu.com/s/1qWr4AF6
2.5 日志分析
日志配置
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查看具体错
误原因。
正常启动状态的warpper日志为:
STATUS | wrapper | 2015/04/12 15:05:00 | --> Wrapper Started as Daemon
STATUS | wrapper | 2015/04/12 15:05:00 | Launching a JVM...
INFO | jvm 1 | 2015/04/12 15:05:01 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
INFO | jvm 1 | 2015/04/12 15:05:01 | Copyright 1999-2006 Tanuki Software, Inc. All Rights Reserved.
INFO | jvm 1 | 2015/04/12 15:05:01 |
INFO | jvm 1 | 2015/04/12 15:05:01 | log4j 2015-04-12 15:05:01 [./conf/log4j.xml] load completed.
INFO | jvm 1 | 2015/04/12 15:05:02 | MyCAT Server startup successfully. see logs in logs/mycat.log
如果启动异常会有对应的异常信息,比如:
STATUS | wrapper | 2015/02/14 01:43:44 | --> Wrapper Started as Daemon
STATUS | wrapper | 2015/02/14 01:43:44 | Launching a JVM...
INFO | jvm 1 | 2015/02/14 01:43:45 | Error: Exception thrown by the agent :
java.rmi.server.ExportException: Port already in use: 1984; nested exception is:
INFO | jvm 1 | 2015/02/14 01:43:45 | java.net.BindException: Address already in use
ERROR | wrapper | 2015/02/14 01:43:45 | JVM exited while loading the application.
日志显示异常原因为java.net.BindException: Address already in use,也就是端口占用,很有可能是原有服务未停止,或者Mycat默
认端口被其他程序占用,正常启动成功后会有mycat.log日志,如果服务未启动成功不会有对应的日志。
mycat日志
下面看一下info级别小成功启动的日志。
04-29 21:46:59.121 INFO [main] (PhysicalDBPool.java:81) -total resouces of dataHost jdbchost is :4
04-29 21:46:59.126 INFO [main] (PhysicalDBPool.java:81) -total resouces of dataHost jdbchost2 is :4
04-29 21:46:59.143 INFO [main] (CacheService.java:125) -create layer cache pool TableID2DataNodeCache of
type encache ,default cache size 10000 ,default expire seconds18000
04-29 21:46:59.145 INFO [main] (DefaultLayedCachePool.java:80) -create child Cache: TESTDB_ORDERS for
layered cache TableID2DataNodeCache, size 50000, expire seconds 18000
04-29 21:46:59.472 INFO [main] (DynaClassLoader.java:35) -dyna class load from E:\MyProject\Mycat-Server
\main\catlet,and auto check for class file modified every 60 seconds
04-29 21:46:59.477 INFO [main] (MycatServer.java:192) -===============================================
04-29 21:46:59.478 INFO [main] (MycatServer.java:193) -MyCat is ready to startup ...
04-29 21:46:59.478 INFO [main] (MycatServer.java:203) -Startup processors ...,total processors:4,aio
thread pool size:8
each process allocated socket buffer pool bytes ,buffer chunk size:4096 buffer pool's
capacity(buferPool/bufferChunk) is:4000
04-29 21:46:59.479 INFO [main] (MycatServer.java:204) -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=4, processorExecutor=8, 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=16384000, processorBufferChunk=4096, defaultMaxLimit=100, sequnceHandlerType=1,
sqlInterceptor=org.opencloudb.interceptor.impl.DefaultSqlInterceptor, sqlInterceptorType=select,
sqlInterceptorFile=E:\MyProject\Mycat-Server/logs/sql.txt, mutiNodeLimitType=0, mutiNodePatchSize=100,
defaultSqlParser=druidparser, usingAIO=0, packetHeaderSize=4, maxPacketSize=16777216, mycatNodeId=1]
04-29 21:46:59.506 INFO [main] (MycatServer.java:262) -using nio network handler
04-29 21:46:59.530 INFO [main] (MycatServer.java:280) -$_MyCatManager is started and listening on 9066
04-29 21:46:59.530 INFO [main] (MycatServer.java:284) -$_MyCatServer is started and listening on 8066
04-29 21:46:59.530 INFO [main] (MycatServer.java:286) -===============================================
04-29 21:46:59.530 INFO [main] (MycatServer.java:289) -Initialize dataHost ...
04-29 21:46:59.531 INFO [main] (PhysicalDBPool.java:267) -init backend myqsl source ,create connections
total 10 for master index :0
04-29 21:46:59.533 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.536 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.537 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.537 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.537 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.538 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.538 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.538 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.539 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.539 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.598 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=5, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88952, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=4, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88953, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=3, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88951, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.598 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=2, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88949, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=8, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88956, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=7, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88954, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=1, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88950, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.599 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=6, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88955, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.600 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=10, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88958, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.603 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=9, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=88957, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.739 INFO [main] (PhysicalDBPool.java:296) -init result :finished 10 success 10 target
count:10
04-29 21:46:59.739 INFO [main] (PhysicalDBPool.java:238) -jdbchost index:0 init success
04-29 21:46:59.739 INFO [main] (PhysicalDBPool.java:267) -init backend myqsl source ,create connections
total 10 for master index :0
04-29 21:46:59.739 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.740 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.741 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.741 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.741 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:46:59.925 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=18, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17135, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.926 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=13, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17132, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.926 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=17, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17138, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:46:59.971 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=14, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17134, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:00.032 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=11, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17130, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:00.034 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=12, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17131, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:00.035 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=20, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17136, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:00.035 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=19, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17139, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:01.255 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=15, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17133, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:01.258 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=16, lastTime=1430315219133, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17137, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:47:01.343 INFO [main] (PhysicalDBPool.java:296) -init result :finished 10 success 10 target
count:10
04-29 21:47:01.343 INFO [main] (PhysicalDBPool.java:238) -jdbchost2 index:0 init success
MyCAT Server startup successfully. see logs in logs/mycat.log
04-29 21:51:21.846 INFO [main] (PhysicalDBPool.java:81) -total resouces of dataHost jdbchost is :4
04-29 21:51:21.848 INFO [main] (PhysicalDBPool.java:81) -total resouces of dataHost jdbchost2 is :4
该部分日志可以看到配置的数据源相关信息,上面是两个数据源连接datahost
04-29 21:51:21.856 INFO [main] (CacheService.java:125) -create layer cache pool TableID2DataNodeCache of
type encache ,default cache size 10000 ,default expire seconds18000
04-29 21:51:21.857 INFO [main] (DefaultLayedCachePool.java:80) -create child Cache: TESTDB_ORDERS for
layered cache TableID2DataNodeCache, size 50000, expire seconds 18000
04-29 21:51:22.104 INFO [main] (DynaClassLoader.java:35) -dyna class load from E:\MyProject\Mycat-Server
\main\catlet,and auto check for class file modified every 60 seconds
该部分描述了Mycat的缓存信息及动态类加载信息。
04-29 21:51:22.107 INFO [main] (MycatServer.java:203) -Startup processors ...,total processors:4,aio
thread pool size:8
each process allocated socket buffer pool bytes ,buffer chunk size:4096 buffer pool's
capacity(buferPool/bufferChunk) is:4000
04-29 21:51:22.108 INFO [main] (MycatServer.java:204) -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=4, processorExecutor=8, 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=16384000, processorBufferChunk=4096, defaultMaxLimit=100, sequnceHandlerType=1,
sqlInterceptor=org.opencloudb.interceptor.impl.DefaultSqlInterceptor, sqlInterceptorType=select,
sqlInterceptorFile=E:\MyProject\Mycat-Server/logs/sql.txt, mutiNodeLimitType=0, mutiNodePatchSize=100,
defaultSqlParser=druidparser, usingAIO=0, packetHeaderSize=4, maxPacketSize=16777216, mycatNodeId=1]
04-29 21:51:22.131 INFO [main] (MycatServer.java:262) -using nio network handler
该部分描述了Mycat线程池、buffer、连接池等等所有的配置信息,通过该启动项可以得知当前运行的Mycat个参数调整情况,
生产环境下需要做部分参数调整,可以根据该日志分析参数情况。
04-29 21:58:35.407 INFO [main] (MycatServer.java:280) -$_MyCatManager is started and listening on 9066
04-29 21:58:35.408 INFO [main] (MycatServer.java:284) -$_MyCatServer is started and listening on 8066
该部分描述了Mycat启动端口。
04-29 21:58:35.408 INFO [main] (MycatServer.java:289) -Initialize dataHost ...
04-29 21:58:35.408 INFO [main] (PhysicalDBPool.java:267) -init backend myqsl source ,create connections
total 10 for master index :0
04-29 21:58:35.410 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.412 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.413 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.413 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.413 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.414 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.414 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.414 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.414 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.415 INFO [main] (PhysicalDatasource.java:356) -not ilde connection in pool,create new
connection for masterConnectionMeta [schema=mycat_node1, charset=utf8, txIsolation=-1, autocommit=true]
04-29 21:58:35.463 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=4, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89015, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.464 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=6, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89018, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.463 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=5, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89017, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.463 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=7, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89019, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.464 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=1, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89013, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.464 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=2, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89016, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.465 INFO [$_NIOREACTOR-3-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=3, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89014, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.467 INFO [$_NIOREACTOR-0-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=8, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89020, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.471 INFO [$_NIOREACTOR-1-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=9, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89021, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.472 INFO [$_NIOREACTOR-2-RW] (GetConnectionHandler.java:66) -connected successfuly
MySQLConnection [id=10, lastTime=1430315915098, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89022, charset=utf8, txIsolation=0, autocommit=true, attachment=null,
respHandler=null, host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 21:58:35.615 INFO [main] (PhysicalDBPool.java:296) -init result :finished 10 success 10 target
count:10
04-29 21:58:35.615 INFO [main] (PhysicalDBPool.java:238) -jdbchost index:0 init success
04-29 21:58:35.615 INFO [main] (PhysicalDBPool.java:267) -init backend myqsl source ,create connections
total 10 for master index :0
该部分描述了Mycat时后端连接池的初始化过程。
如果某个连接断掉或异常心跳检测会有对应的日志如:
04-29 22:01:07.274 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr ,[thread=$_NIOConnector,class=MySQLDetector,host=192.168.0.2,port=33061,localPort=0,schema=null]
该日志是心跳检测到连接异常关闭后端连接的日志,可以通过该日志查看后端数据连接状态。
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.292 DEBUG [$_NIOREACTOR-1-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=13, lastTime=1430316370226, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17188, charset=utf8, txIsolation=3, autocommit=true, attachment=dn2{SHOW
STATUS}, respHandler=SingleNodeHandler [node=dn2{SHOW STATUS}, packetId=60], host=116.236.223.115,
port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@7cf13e82, writeQueue=0,
modifiedSQLExecuted=false]
04-29 22:06:10.292 DEBUG [$_NIOREACTOR-1-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=13, lastTime=1430316370226, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17188, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.293 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.293 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 -> dn1{SHOW STATUS}
} rrs
04-29 22:06:10.293 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for
dataHost:jdbchost
04-29 22:06:10.293 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=3, lastTime=1430316370288, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=89066, charset=utf8, txIsolation=0, autocommit=true, attachment=dn1{SHOW STATUS},
respHandler=SingleNodeHandler [node=dn1{SHOW STATUS}, packetId=0], host=121.40.121.133, port=3306,
statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.306 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=3, lastTime=1430316370288, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89066, charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SHOW
STATUS}, respHandler=SingleNodeHandler [node=dn1{SHOW STATUS}, packetId=60], host=121.40.121.133, port=3306,
statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@4bd38cb3, writeQueue=0,
modifiedSQLExecuted=false]
04-29 22:06:10.306 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=3, lastTime=1430316370288, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=89066, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=121.40.121.133, port=3306, 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 * 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
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=org.opencloudb.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=org.opencloudb.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=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=121.40.121.133, port=3306, statusSync=org.opencloudb.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], PROVINCE_CODE=ColMeta [colIndex=3, colType=253],
USER_ID=ColMeta [colIndex=0, colType=3], CREATE_TIME=ColMeta [colIndex=2, colType=12]]
04-29 22:06:10.434 DEBUG [$_NIOREACTOR-1-RW] (MultiNodeQueryHandler.java:226) -on row end reseponse
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=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=121.40.121.133, port=3306, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@7485fef2,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.434 DEBUG [$_NIOREACTOR-1-RW] (NonBlockingSession.java:246) -release connection
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=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=121.40.121.133, port=3306, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@7485fef2,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.435 DEBUG [$_NIOREACTOR-1-RW] (PhysicalDatasource.java:386) -release channel 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=null, respHandler=null,
host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.481 DEBUG [$_NIOREACTOR-3-RW] (MultiNodeQueryHandler.java:165) -received ok response
,executeResponse:false from MySQLConnection [id=11, lastTime=1430316370409, schema=mycat_node1, old
shema=mycat_node1, borrowed=true, fromSlaveDB=false, threadId=17189, charset=utf8, txIsolation=3,
autocommit=true, attachment=dn2{SELECT *
FROM t_user t
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=116.236.223.115, port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@6a95ec91,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.482 DEBUG [$_NIOREACTOR-3-RW] (MultiNodeQueryHandler.java:226) -on row end reseponse
MySQLConnection [id=11, lastTime=1430316370409, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17189, charset=utf8, txIsolation=3, autocommit=true, attachment=dn2{SELECT *
FROM t_user t
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=116.236.223.115, port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@6a95ec91,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.482 DEBUG [$_NIOREACTOR-3-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=11, lastTime=1430316370409, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17189, charset=utf8, txIsolation=3, autocommit=true, attachment=dn2{SELECT *
FROM t_user t
LIMIT 100}, respHandler=org.opencloudb.mysql.nio.handler.MultiNodeQueryHandler@3ff70d3c,
host=116.236.223.115, port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@6a95ec91,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.482 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=11, lastTime=1430316370409, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17189, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.484 DEBUG [BusinessExecutor6] (DataMergeService.java:130) -prepare mpp merge result for
select * from t_user t
04-29 22:06:10.485 DEBUG [BusinessExecutor6] (MultiNodeQueryHandler.java:287) -output merge result ,total
data 16 start :0 end :100 package id start:6
04-29 22:06:10.485 DEBUG [BusinessExecutor6] (MultiNodeQueryHandler.java:308) -last packet id:23
04-29 22:06:10.485 DEBUG [BusinessExecutor6] (DataMergeService.java:312) -clear data
04-29 22:06:10.491 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.491 DEBUG [$_NIOREACTOR-3-RW] (DataMergeService.java:312) -clear data
04-29 22:06:10.492 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.492 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for
dataHost:jdbchost2
04-29 22:06:10.492 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=12, lastTime=1430316370489, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17186, 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.554 DEBUG [$_NIOREACTOR-0-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=12, lastTime=1430316370489, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17186, charset=utf8, txIsolation=3, autocommit=true, attachment=dn2{SHOW
STATUS}, respHandler=SingleNodeHandler [node=dn2{SHOW STATUS}, packetId=60], host=116.236.223.115,
port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@364c4b05, writeQueue=0,
modifiedSQLExecuted=false]
04-29 22:06:10.554 DEBUG [$_NIOREACTOR-0-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=12, lastTime=1430316370489, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17186, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.589 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
`mycat_node1`.`t_user` LIMIT 0
04-29 22:06:10.590 DEBUG [$_NIOREACTOR-3-RW] (EnchachePool.java:76) -SQLRouteCache miss cache
,key:mycatSELECT * FROM `mycat_node1`.`t_user` LIMIT 0
04-29 22:06:10.592 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
`mycat_node1`.`t_user` LIMIT 0, route={
1 -> dn1{SELECT * FROM `mycat_node1`.`t_user` LIMIT 0}
} rrs
04-29 22:06:10.592 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for
dataHost:jdbchost
04-29 22:06:10.592 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=4, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=89064, charset=utf8, txIsolation=0, autocommit=true, attachment=dn1{SELECT * FROM
`mycat_node1`.`t_user` LIMIT 0}, respHandler=SingleNodeHandler [node=dn1{SELECT * FROM
`mycat_node1`.`t_user` LIMIT 0}, packetId=0], host=121.40.121.133, port=3306, statusSync=null, writeQueue=0,
modifiedSQLExecuted=false]
04-29 22:06:10.603 DEBUG [$_NIOREACTOR-0-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=4, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=89064, charset=utf8, txIsolation=3, autocommit=true, attachment=dn1{SELECT *
FROM `mycat_node1`.`t_user` LIMIT 0}, respHandler=SingleNodeHandler [node=dn1{SELECT * FROM
`mycat_node1`.`t_user` LIMIT 0}, packetId=6], host=121.40.121.133, port=3306,
statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@4792ba63, writeQueue=0,
modifiedSQLExecuted=false]
04-29 22:06:10.603 DEBUG [$_NIOREACTOR-0-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=4, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=89064, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=121.40.121.133, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.603 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 COLUMNS FROM
`mycat_node1`.`t_user`
04-29 22:06:10.603 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 COLUMNS FROM
mycat_node1.t_user, route={
1 -> dn2{SHOW COLUMNS FROM t_user}
} rrs
04-29 22:06:10.604 DEBUG [$_NIOREACTOR-3-RW] (PhysicalDBPool.java:417) -select read source master for
dataHost:jdbchost2
04-29 22:06:10.604 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=16, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17191, charset=utf8, txIsolation=0, autocommit=true, attachment=dn2{SHOW COLUMNS FROM t_user},
respHandler=SingleNodeHandler [node=dn2{SHOW COLUMNS FROM t_user}, packetId=0], host=116.236.223.115,
port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.665 DEBUG [$_NIOREACTOR-0-RW] (NonBlockingSession.java:246) -release connection
MySQLConnection [id=16, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true,
fromSlaveDB=false, threadId=17191, charset=utf8, txIsolation=3, autocommit=true, attachment=dn2{SHOW COLUMNS
FROM t_user}, respHandler=SingleNodeHandler [node=dn2{SHOW COLUMNS FROM t_user}, packetId=12],
host=116.236.223.115, port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@278806c4,
writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:10.665 DEBUG [$_NIOREACTOR-0-RW] (PhysicalDatasource.java:386) -release channel MySQLConnection
[id=16, lastTime=1430316370591, schema=mycat_node1, old shema=mycat_node1, borrowed=true, fromSlaveDB=false,
threadId=17191, charset=utf8, txIsolation=3, autocommit=true, attachment=null, respHandler=null,
host=116.236.223.115, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false]
04-29 22:06:21.332 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:06:21.334 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:06:42.333 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:06:42.334 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:03.326 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:03.344 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:24.327 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:24.345 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:45.332 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
04-29 22:07:45.355 INFO [$_NIOConnector] (AbstractConnection.java:398) -close connection,reason:hearbeat
connecterr
,[thread=$_NIOConnector,class=MySQLDetector,host=116.236.223.115,port=33071,localPort=0,schema=null]
通过该日志可以看到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节点执行。
异常日志
java.sql.SQLSyntaxErrorException: com.alibaba.druid.sql.parser.ParserException: syntax error, error in
:'elect * from t_user t where t.',expect IDENTIFIER, actual IDENTIFIER elect
at
org.opencloudb.route.impl.DruidMycatRouteStrategy.routeNormalSqlWithAST(DruidMycatRouteStrategy.java:44)
at org.opencloudb.route.impl.AbstractRouteStrategy.route(AbstractRouteStrategy.java:52)
at org.opencloudb.route.RouteService.route(RouteService.java:118)
at org.opencloudb.server.ServerConnection.routeEndExecuteSQL(ServerConnection.java:165)
at org.opencloudb.server.ServerConnection.execute(ServerConnection.java:154)
at org.opencloudb.server.ServerQueryHandler.query(ServerQueryHandler.java:125)
at org.opencloudb.net.FrontendConnection.query(FrontendConnection.java:250)
at org.opencloudb.net.handler.FrontendCommandHandler.handle(FrontendCommandHandler.java:56)
at org.opencloudb.net.FrontendConnection.handle(FrontendConnection.java:357)
at org.opencloudb.net.AbstractConnection.onReadData(AbstractConnection.java:276)
at org.opencloudb.net.NIOSocketWR.asynRead(NIOSocketWR.java:186)
at org.opencloudb.net.AbstractConnection.asynRead(AbstractConnection.java:238)
at org.opencloudb.net.NIOReactor$RW.run(NIOReactor.java:97)
at java.lang.Thread.run(Thread.java:745)
Caused by: com.alibaba.druid.sql.parser.ParserException: syntax error, error in :'elect * from t_user t
where t.',expect IDENTIFIER, actual IDENTIFIER elect
at com.alibaba.druid.sql.parser.SQLParser.printError(SQLParser.java:229)
at com.alibaba.druid.sql.parser.SQLStatementParser.parseStatementList(SQLStatementParser.java:325)
at com.alibaba.druid.sql.parser.SQLStatementParser.parseStatement(SQLStatementParser.java:1655)
at
org.opencloudb.route.impl.DruidMycatRouteStrategy.routeNormalSqlWithAST(DruidMycatRouteStrategy.java:41)
... 13 more
如上面日志异常原因为sql错误导致sql解析器无法解析sql,通过分析错误日志可以找到具体的出错原因。
Mycat日志很重要,当发现SQL执行有异常的时候,大多数情况下,都可以通过分析Mycat日志来定位错误,当发现Bug存在的
时候,也建议把相关日志信息附上,一并提交github issue