日志分析

mycat的日志文件配置為MYCAT_HOME/conf/log4j.xml,結(jié)構(gòu)為：

<?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>

日志配置是標(biāo)準(zhǔn)的log4j配置，其中：

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

是日志文件的存放目錄。

<root> <level value="debug" /> <appender-ref ref="ConsoleAppender" /> </root>

是日志的級(jí)別，生成環(huán)境下建議將級(jí)別調(diào)整為info/ware,如果是研究測(cè)試，特別是碰到異常可以通過開啟debug模式觀察日志的信息查找異常原因。
1 warpper日志：
目前Mycat的啟動(dòng)是經(jīng)過warapper封裝成啟動(dòng)腳本，所以日志也會(huì)有其相關(guān)的日志文件：${MYCAT_HOME}/logs/warapper.log,再啟動(dòng)時(shí)候如果系統(tǒng)環(huán)境配置錯(cuò)誤或缺少配置時(shí)，導(dǎo)致Mycat無法啟動(dòng)，可以通過查看warrpper.log查看具體錯(cuò)誤原因。
正常啟動(dòng)狀態(tài)的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

如果啟動(dòng)異常會(huì)有對(duì)應(yīng)的異常信息，比如：

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.

日志顯示異常原因?yàn)閖ava.net.BindException: Address already in use,也就是端口占用，很有可能是原有服務(wù)未停止，或者M(jìn)ycat默認(rèn)端口被其他程序占用，正常啟動(dòng)成功后會(huì)有mycat.log日志，如果服務(wù)未啟動(dòng)成功不會(huì)有對(duì)應(yīng)的日志。
2 mycat日志
下面看一下info級(jí)別小成功啟動(dòng)的日志。

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, 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

該部分日志可以看到配置的數(shù)據(jù)源相關(guān)信息，上面是兩個(gè)數(shù)據(jù)源連接
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的緩存信息及動(dòng)態(tài)類加載信息。

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、連接池等等所有的配置信息，通過該啟動(dòng)項(xiàng)可以得知當(dāng)前運(yùn)行的Mycat個(gè)參數(shù)調(diào)整情況，生產(chǎn)環(huán)境下需要做部分參數(shù)調(diào)整，可以根據(jù)該日志分析參數(shù)情況。

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啟動(dòng)端口。

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, 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時(shí)后端連接池的初始化過程。
如果某個(gè)連接斷掉或異常心跳檢測(cè)會(huì)有對(duì)應(yīng)的日志如：

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]

該日志是心跳檢測(cè)到連接異常關(guān)閉后端連接的日志，可以通過該日志查看后端數(shù)據(jù)連接狀態(tài)。
3 debug模式下分析sql執(zhí)行
下面分析sql：select * from t_user t; 的執(zhí)行

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 * 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],

通過該日志可以看到Mycat整個(gè)執(zhí)行的計(jì)劃。
其中最重要的是sql路由的計(jì)劃，可以看到sql具體被分配到那個(gè)分片執(zhí)行：

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上同時(shí)執(zhí)行，如果某個(gè)某個(gè)sql通過緩存、分片規(guī)則或者注解指定只會(huì)在某個(gè)分片執(zhí)行，則sql只會(huì)被分配到到某個(gè)分片，例如：
sql=select * from t_user t where t.user_id=121;該條數(shù)據(jù)只在分片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節(jié)點(diǎn)執(zhí)行。
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 org.opencloudb.route.impl.DruidMycatRouteStrategy.routeNormalSqlWithAST(DruidMycatRouteStrategy.java:44) 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.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.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) 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

如上面日志異常原因?yàn)閟ql錯(cuò)誤導(dǎo)致sql解析器無法解析sql，通過分析錯(cuò)誤日志可以找到具體的出錯(cuò)原因。
Mycat日志很重要，當(dāng)發(fā)現(xiàn)SQL執(zhí)行有異常的時(shí)候，大多數(shù)情況下，都可以通過分析Mycat日志來定位錯(cuò)誤，當(dāng)發(fā)現(xiàn)Bug存在的時(shí)候，也建議把相關(guān)日志信息附上，一并提交github issue。

總結(jié)

以上是生活随笔為你收集整理的日志分析---携来百侣曾游，忆往昔峥嵘岁月稠的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。