快速学习-Mycat日志分析

cwl_java

发布于 2021-08-30 11:32:11

4710

发布于 2021-08-30 11:32:11

文章被收录于专栏：cwl_Javacwl_Java

第 5 章日志分析

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

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

是日志文件的存放目录。

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

5.1 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. AllRights 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 日志，如果服务未启动成功不会有对应的日志。也可以去修改 conf 文件夹里的 wrapper.conf 里的 wrapper.java.additional.7=-Dcom.sun.management.jmxremote.port=1984，server.xml 的8066和9066，这方法适合一台机器上两个 mycat 或者 1984,8066,9066 端口被其它应用占用的情况。

5.2 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\MycatServer\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, 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\MycatServer\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=io.mycat.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 networkhandler

该部分描述了 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 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,schem 
a=null]

该日志是心跳检测到连接异常关闭后端连接的日志，可以通过该日志查看后端数据连接状态。

5.3 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
4-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=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 具体被分配到那个分片执行：

4-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 节点执行。

5.4 异常日志

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
io.mycat.route.impl.DruidMycatRouteStrategy.routeNormalSqlWithAST(DruidMycatRouteStrategy.java:44) 
atio.mycat.route.impl.AbstractRouteStrategy.route(AbstractRouteStrategy.java:52)
at io.mycat.route.RouteService.route(RouteService.java:118)
at io.mycat.server.ServerConnection.routeEndExecuteSQL(ServerConnection.java:165) 
at io.mycat.server.ServerConnection.execute(ServerConnection.java:154)
at io.mycat.server.ServerQueryHandler.query(ServerQueryHandler.java:125) 
at io.mycat.net.FrontendConnection.query(FrontendConnection.java:250)
at io.mycat.net.handler.FrontendCommandHandler.handle(FrontendCommandHandler.java:56) 
at io.mycat.net.FrontendConnection.handle(FrontendConnection.java:357)
at io.mycat.net.AbstractConnection.onReadData(AbstractConnection.java:276) 
at io.mycat.net.NIOSocketWR.asynRead(NIOSocketWR.java:186)
at io.mycat.net.AbstractConnection.asynRead(AbstractConnection.java:238) 
at io.mycat.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
io.mycat.route.impl.DruidMycatRouteStrategy.routeNormalSqlWithAST(DruidMycatRouteStrategy.java:41)
... 13 more

如上面日志异常原因为 sql 错误导致 sql 解析器无法解析 sql，通过分析错误日志可以找到具体的出错原因。

Mycat 日志很重要，当发现 SQL 执行有异常的时候，大多数情况下，都可以通过分析 Mycat 日志来定位错误，当发现 Bug 存在的时候，也建议把相关日志信息附上，一并提交 github issue。

本文参与腾讯云自媒体分享计划，分享自作者个人站点/博客。

原始发表：2021-02-07 ，如有侵权请联系 cloudcommunity@tencent.com 删除

sql

java

javascript

xml

本文分享自作者个人站点/博客前往查看

如有侵权，请联系 cloudcommunity@tencent.com 删除。

本文参与腾讯云自媒体分享计划，欢迎热爱写作的你一起参与！

登录后参与评论

0 条评论

热度