MyCAT 日志文件描述

柔情只为你懂 2022-08-09 03:25 220阅读 0赞

MyCat是一个基于cobar兴起的开源数据库中间件系统，当前深受广大开源爱好者的追捧以及DBA粉丝们的广泛研究。主要是面对解决高并发，高负载，海量存储等屏颈。与任何应用软件一样，MyCAT也有自身的日志文件用于记录MyCAT运行时的相关信息用于排错与跟踪。本文主要描述其日志文件部分。  
  
    有关快速安装体验MyCAT请参考：[快速体验MyCAT][MyCAT]  
  
一、日志配置  
\#\#\# 环境描述  
\#\#\# 当前基于windows 7安装了mycat  
\#\#\# 两台mysql主机，分别为192.168.1.204:3306,192.168.1.143:3307  
  
\#\#\#查看日志文件配置  
D:\\>type mycat\\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"/>                          //记录方式，此时为append  
    <param name="MaxFileSize" value="1000KB"/>                    //每个日志文件大小  
    <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="info" />       //是日志的级别，生成环境下建议将级别调整为 info/ware。  
                         //如果是研究测试，特别是碰到异常可以通过开启 debug 模式观察日志的信息查找异常原因。  
    <appender-ref ref="FILE" />  
       
  </root>  
  
</log4j:configuration>  
  
二、日志分析  
1、warpper.log日志  
warpper 日志：mycat启动，停止，添加为服务等都会记录到此日志文件，如果系统环境配置错误或缺少配置时，导致 Mycat 无法  
启动，可以通过查看 warrpper.log 定位具体错误原因。  
warrpper.log可以删除，删除后会自动重新生成该日志  
\#\#\#如果启动异常会有对应的异常信息，比如：  
STATUS | wrapper  | 2015/09/25 09:26:36 | --> Wrapper Started as Service  
STATUS | wrapper  | 2015/09/25 09:26:36 | Launching a JVM...  
INFO   | jvm 1    | 2015/09/25 09:26:37 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org  
INFO   | jvm 1    | 2015/09/25 09:26:37 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.  
INFO   | jvm 1    | 2015/09/25 09:26:37 |   
INFO   | jvm 1    | 2015/09/25 09:26:37 |   
INFO   | jvm 1    | 2015/09/25 09:26:37 | WrapperSimpleApp: Encountered an error running main: java.lang.ExceptionInInitializerError  
INFO   | jvm 1    | 2015/09/25 09:26:37 | java.lang.ExceptionInInitializerError  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at org.opencloudb.MycatStartup.main(MycatStartup.java:46)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at java.lang.reflect.Method.invoke(Method.java:606)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at org.tanukisoftware.wrapper.WrapperSimpleApp.run(WrapperSimpleApp.java:240)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | at java.lang.Thread.run(Thread.java:745)  
INFO   | jvm 1    | 2015/09/25 09:26:37 | Caused by: org.opencloudb.config.util.ConfigException: org.xml.sax.SAXParseException;   
  lineNumber: 26; columnNumber: 5; 元素类型 "dataHost" 必须由匹配的结束标记 "</dataHost>" 终止。   //这里说明了错误原因  
INFO   | jvm 1    | 2015/09/25 09:26:37 | ... 13 more  
STATUS | wrapper  | 2015/09/25 09:26:39 | <-- Wrapper Stopped  
STATUS | wrapper  | 2015/09/25 09:28:10 | --> Wrapper Started as Service  
  
\#\#\#正常启动状态的 warpper 日志为：  
STATUS | wrapper  | 2015/09/25 11:15:52 | Starting the Mycat-server service...  
STATUS | wrapper  | 2015/09/25 11:15:52 | --> Wrapper Started as Service  
STATUS | wrapper  | 2015/09/25 11:15:52 | Launching a JVM...  
INFO   | jvm 1    | 2015/09/25 11:15:52 | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org  
INFO   | jvm 1    | 2015/09/25 11:15:52 |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.  
INFO   | jvm 1    | 2015/09/25 11:15:52 |   
INFO   | jvm 1    | 2015/09/25 11:15:53 | log4j 2015-09-25 11:15:53 \[./conf/log4j.xml\] load completed.  
INFO   | jvm 1    | 2015/09/25 11:15:53 | MyCAT Server startup successfully. see logs in logs/mycat.log  
STATUS | wrapper  | 2015/09/25 11:15:56 | Mycat-server started.  
  
2、mycat.log日志  
mycat.log为mycat主要日志文件，记录了启动时分配的相关buffer信息，数据源连接信息，连接池，动态类加载信息等等  
在log4j.xml文件中进行相关配置，如保留个数，大小，字符集，日志文件大小等。  
非启动状态下可以删除，启动后会自动生成该日志文件  
  
日志的级别为info时的相关信息:  
以下日志部分为描述了mycat初始相关参数的配置信息，如Mycat 线程池、 buffer、连接池等等所有的配置信息。  
09/25 15:13:19.257   INFO \[WrapperSimpleAppMain\] (MycatServer.java:195) -===============================================  
09/25 15:13:19.257   INFO \[WrapperSimpleAppMain\] (MycatServer.java:196) -MyCat is ready to startup ...  
09/25 15:13:19.258   INFO \[WrapperSimpleAppMain\] (MycatServer.java:206) -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  
09/25 15:13:19.258   INFO \[WrapperSimpleAppMain\] (MycatServer.java:207) -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=0, sqlInterceptor=org.opencloudb.interceptor.impl.DefaultSqlInterceptor, sqlInterceptorType=select,   
 sqlInterceptorFile=D:\\mycat/logs/sql.txt, mutiNodeLimitType=0, mutiNodePatchSize=100, defaultSqlParser=druidparser, usingAIO=0,   
 packetHeaderSize=4, maxPacketSize=16777216, mycatNodeId=1\]   
09/25 15:13:19.277   INFO \[WrapperSimpleAppMain\] (MycatServer.java:266) -using nio network handler   
09/25 15:13:19.290   INFO \[WrapperSimpleAppMain\] (MycatServer.java:284) -$\_MyCatManager is started and listening on 9066  
09/25 15:13:19.290   INFO \[WrapperSimpleAppMain\] (MycatServer.java:288) -$\_MyCatServer is started and listening on 8066  
  
以下部分为分片主机的相关信息，分别初始化了10个连接到2个不同的分片主机  
这个是来自配置文件schema.xml里定义的dataHost中minCon="10"  
09/25 15:13:19.290   INFO \[WrapperSimpleAppMain\] (MycatServer.java:290) -===============================================  
09/25 15:13:19.291   INFO \[WrapperSimpleAppMain\] (MycatServer.java:293) -Initialize dataHost ...  
09/25 15:13:19.291   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:272) -init backend myqsl source ,create connections total 10 for hostM1 index :0  
09/25 15:13:19.291   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.293   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.293   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.294   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.294   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.294   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.294   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.294   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.295   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.295   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db1  
09/25 15:13:19.309   INFO \[$\_NIOREACTOR-1-RW\] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection \[id=1, lastTime=1443165199309,  
 schema=db1, old shema=db1, borrowed=true, fromSlaveDB=false, threadId=363, charset=latin1, txIsolation=0, autocommit=true, attachment=null,   
 respHandler=null, host=192.168.1.204, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:13:19.309   INFO \[$\_NIOREACTOR-3-RW\] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection \[id=3, lastTime=1443165199309,  
 schema=db1, old shema=db1, borrowed=true, fromSlaveDB=false, threadId=365, charset=latin1, txIsolation=0, autocommit=true, attachment=null,   
 respHandler=null, host=192.168.1.204, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
    ..........  
09/25 15:13:19.395   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:301) -init result :finished 10 success 10 target count:10  
09/25 15:13:19.395   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:243) -192.168.1.204 index:0 init success  
09/25 15:13:19.395   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:272) -init backend myqsl source ,create connections total 10 for hostM1 index :0  
09/25 15:13:19.396   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.396   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.396   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.396   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.397   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.397   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.398   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.398   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.399   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.400   INFO \[WrapperSimpleAppMain\] (PhysicalDatasource.java:373) -not ilde connection in pool,create new connection for hostM1 of schema db2  
09/25 15:13:19.409   INFO \[$\_NIOREACTOR-1-RW\] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection \[id=13, lastTime=1443165199409,  
 schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6232, charset=latin1, txIsolation=0, autocommit=true, attachment=null,  
 respHandler=null, host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:13:19.410   INFO \[$\_NIOREACTOR-1-RW\] (GetConnectionHandler.java:66) -connected successfuly MySQLConnection \[id=17, lastTime=1443165199410,   
schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6235, charset=latin1, txIsolation=0, autocommit=true, attachment=null,  
 respHandler=null, host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
     ...........  
09/25 15:13:19.500   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:301) -init result :finished 10 success 10 target count:10  
09/25 15:13:19.500   INFO \[WrapperSimpleAppMain\] (PhysicalDBPool.java:243) -192.168.1.143 index:0 init success  
  
以下部分是一个成功连接到9066的信息  
09/25 15:13:51.468   INFO \[$\_NIOREACTOR-1-RW\] (FrontendAuthenticator.java:164) -\[thread=$\_NIOREACTOR-1-RW,  
 class=ManagerConnection,id=1,host=0:0:0:0:0:0:0:1,port=9066,schema=testdb\]'test' login success  
  
日志的级别为debug时的相关信息:  
修改日志配置文件log4j.xml，value值改为"debug"，如下：  
<level value="debug" />  
  
mysql:9600>reload @@config\_all;  
Query OK, 1 row affected (0.23 sec)  
Reload config success  
  
\--发布查询  
mysql:8066>select \* from goods;  
\+----+-------+  
| id | val   |  
\+----+-------+  
|  1 | apple |  
\+----+-------+  
  
\--相关的日志信息，//这里为路由的信息，即sql最终在哪个分片节点执行  
09/25 15:52:07.235  DEBUG \[$\_NIOREACTOR-0-RW\] (ServerQueryHandler.java:56) -ServerConnection \[id=4, schema=testdb, host=0:0:0:0:0:0:0:1,  
 user=test,txIsolation=3, autocommit=true, schema=testdb\]select \* from goods  
09/25 15:52:07.235  DEBUG \[$\_NIOREACTOR-0-RW\] (EnchachePool.java:76) -SQLRouteCache  miss cache ,key:testdbselect \* from goods  
09/25 15:52:07.236  DEBUG \[$\_NIOREACTOR-0-RW\] (NonBlockingSession.java:113) -ServerConnection \[id=4, schema=testdb, host=0:0:0:0:0:0:0:1,   
user=test,txIsolation=3, autocommit=true, schema=testdb\]select \* from goods, route=\{  
   1 -> dn2\{SELECT \*  
FROM goods  
LIMIT 100\}  
\} rrs   
09/25 15:52:07.236  DEBUG \[$\_NIOREACTOR-0-RW\] (PhysicalDBPool.java:431) -select read source hostM1 for dataHost:192.168.1.143  
09/25 15:52:07.236  DEBUG \[$\_NIOREACTOR-0-RW\] (MySQLConnection.java:442) -con need syn ,total syn cmd 2 commands SET names gbk;  
SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ;schema change:false con:MySQLConnection \[id=33, lastTime=1443167527236,   
schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6242, charset=latin1, txIsolation=0, autocommit=true, attachment=dn2\{SELECT \*  
FROM goods  
LIMIT 100\}, respHandler=SingleNodeHandler \[node=dn2\{SELECT \*  
FROM goods  
LIMIT 100\}, packetId=0\], host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:52:07.238  DEBUG \[$\_NIOREACTOR-2-RW\] (NonBlockingSession.java:230) -release connection MySQLConnection \[id=33,   
lastTime=1443167527222, schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6242, charset=gbk,   
txIsolation=3, autocommit=true, attachment=dn2\{SELECT \*  
FROM goods  
LIMIT 100\}, respHandler=SingleNodeHandler \[node=dn2\{SELECT \*  
FROM goods  
LIMIT 100\}, packetId=5\], host=192.168.1.143, port=3307, statusSync=org.opencloudb.mysql.nio.MySQLConnection$StatusSync@9d2f333, writeQueue=0,   
modifiedSQLExecuted=false\]  
09/25 15:52:07.238  DEBUG \[$\_NIOREACTOR-2-RW\] (PhysicalDatasource.java:403) -release channel MySQLConnection   
\[id=33, lastTime=1443167527222, schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6242, charset=gbk,  
 txIsolation=3, autocommit=true, attachment=null, respHandler=null, host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:52:09.508  DEBUG \[Timer1\] (SQLJob.java:85) -con query sql:select user() to con:MySQLConnection \[id=26,  
 lastTime=1443167529508, schema=db1, old shema=db1, borrowed=true, fromSlaveDB=false, threadId=376, charset=latin1,  
 txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=192.168.1.204, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:52:09.508  DEBUG \[Timer1\] (SQLJob.java:85) -con query sql:select user() to con:MySQLConnection \[id=32,  
 lastTime=1443167529508, schema=db2, old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6245, charset=latin1,  
 txIsolation=0, autocommit=true, attachment=null, respHandler=null, host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:52:09.509  DEBUG \[$\_NIOREACTOR-3-RW\] (PhysicalDatasource.java:403) -release channel MySQLConnection \[id=26, lastTime=1443167529502, schema=db1,  
 old shema=db1, borrowed=true, fromSlaveDB=false, threadId=376, charset=latin1, txIsolation=0, autocommit=true, attachment=null, respHandler=null,  
 host=192.168.1.204, port=3306, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
09/25 15:52:09.509  DEBUG \[$\_NIOREACTOR-1-RW\] (PhysicalDatasource.java:403) -release channel MySQLConnection \[id=32, lastTime=1443167529502, schema=db2,  
 old shema=db2, borrowed=true, fromSlaveDB=false, threadId=6245, charset=latin1, txIsolation=0, autocommit=true, attachment=null, respHandler=null,   
 host=192.168.1.143, port=3307, statusSync=null, writeQueue=0, modifiedSQLExecuted=false\]  
  
以下部分是一个分布在既分布在dn1，又分布在dn2上日志路由信息  
09/25 16:30:26.641  DEBUG \[$\_NIOREACTOR-0-RW\] (EnchachePool.java:76) -SQLRouteCache  miss cache ,key:testdbselect \* from travelrecord  
09/25 16:30:26.649  DEBUG \[$\_NIOREACTOR-0-RW\] (EnchachePool.java:59) -SQLRouteCache add cache ,key:testdbselect \* from travelrecord value:select \*  
 from travelrecord, route=\{  
   1 -> dn1\{SELECT \*  
FROM travelrecord  
LIMIT 100\}  
   2 -> dn2\{SELECT \*  
FROM travelrecord  
LIMIT 100\}  
\}  
09/25 16:30:26.649  DEBUG \[$\_NIOREACTOR-0-RW\] (NonBlockingSession.java:113) -ServerConnection \[id=4, schema=testdb, host=0:0:0:0:0:0:0:1,   
user=test,txIsolation=3, autocommit=true, schema=testdb\]select \* from travelrecord, route=\{  
   1 -> dn1\{SELECT \*  
FROM travelrecord  
LIMIT 100\}  
   2 -> dn2\{SELECT \*  
FROM travelrecord  
LIMIT 100\}  
\} rrs   
09/25 16:30:26.650  DEBUG \[$\_NIOREACTOR-0-RW\] (MultiNodeQueryHandler.java:83) -execute mutinode query select \* from travelrecord  
09/25 16:30:26.668  DEBUG \[$\_NIOREACTOR-0-RW\] (MultiNodeQueryHandler.java:98) -has data merge logic

[MyCAT]: http://blog.csdn.net/leshami/article/details/48968691