码迷，mamicode.com
首页 > 其他好文 > 详细

日志分析---携来百侣曾游，忆往昔峥嵘岁月稠

时间：2017-03-17 11:10:10      阅读：673      评论：0      收藏：0      [点我收藏+]

标签：加载   home   att   ios   charset   doctype   thrown   div   back   

日志分析

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模式观察日志的信息查找异常原因。
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. 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日志，如果服务未启动成功不会有对应的日志。
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\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

该部分日志可以看到配置的数据源相关信息，上面是两个数据源连接
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 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时后端连接池的初始化过程。
如果某个连接断掉或异常心跳检测会有对应的日志如： 

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]

该日志是心跳检测到连接异常关闭后端连接的日志，可以通过该日志查看后端数据连接状态。
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 
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整个执行的计划。
其中最重要的是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节点执行。
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

如上面日志异常原因为sql错误导致sql解析器无法解析sql，通过分析错误日志可以找到具体的出错原因。
Mycat日志很重要，当发现SQL执行有异常的时候，大多数情况下，都可以通过分析Mycat日志来定位错误，当发现Bug存在的时候，也建议把相关日志信息附上，一并提交github issue。

日志分析---携来百侣曾游，忆往昔峥嵘岁月稠

标签：加载   home   att   ios   charset   doctype   thrown   div   back   

原文地址：http://blog.csdn.net/wangshuang1631/article/details/62862563
踩
(0)
赞
(0)
   
举报
评论 一句话评论（0）
登录后才能评论！
分享档案
更多>
2021年07月29日 (22)
2021年07月28日 (40)
2021年07月27日 (32)
2021年07月26日 (79)
2021年07月23日 (29)
2021年07月22日 (30)
2021年07月21日 (42)
2021年07月20日 (16)
2021年07月19日 (90)
2021年07月16日 (35)
周排行
mamicode.com排行更多图片
更多
友情链接
兰亭集智   国之画   百度统计   站长统计   阿里云   chrome插件   新版天听网
关于我们 - 联系我们 - 留言反馈
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码！