title: SpringBoot结合LogBack打印Sql tags:
- SpringBoot
- Mybatis
- logback
- druid categories: springboot date: 2017-12-05 22:09:38
背景
不同的profile下我们需要不同的配置 SpringBoot关于配置在profile玩的飞起
通常我们在开发或者测试环境下都会打开sql日志方便开发调试
方案
mybatis日志
系统中采用mybatis做orm框架我们自然可以通过mybatis的日志来输出
mybatis作为十分优秀的orm中间件自然对于日志多个平台进行了适配
本例中我们采用logback【事实上调用均采用slf4j最佳 这是日志的门面】
protected SqlSessionFactoryBean getSqlSessionFactoryBean(DataSource dataSource) {
SqlSessionFactoryBean factory = new SqlSessionFactoryBean();
factory.setDataSource(dataSource);
factory.setTypeAliasesPackage(MODEL_PACKAGE);
//配置分页插件,详情请查阅官方文档
PageHelper pageHelper = new PageHelper();
Properties properties = new Properties();
properties.setProperty("pageSizeZero", "true");
//分页尺寸为0时查询所有纪录不再执行分页
properties.setProperty("reasonable", "true");
//页码<=0 查询第一页,页码>=总页数查询最后一页
properties.setProperty("supportMethodsArguments", "false");
//支持通过 Mapper 接口参数来传递分页参数
pageHelper.setProperties(properties);
//添加插件
factory.setPlugins(new Interceptor[]{pageHelper, new SoInterceptor(), new MybatisTransactionTimeoutInterceptor()});
org.apache.ibatis.session.Configuration config = new org.apache.ibatis.session.Configuration();
config.setDefaultStatementTimeout(5);
config.setDefaultFetchSize(10000);
config.setDefaultExecutorType(ExecutorType.REUSE);
config.setLogImpl(Slf4jImpl.class);
config.setLogPrefix("dao.");
factory.setConfiguration(config);
return factory;
}
复制代码
注意我们在mybatis的config中使用了Slf4jImpl的实现 同时针对mybatis的日志均加了dao的前缀方便在日志中收集
在logback-spring.xml中定义如下log
<springProfile name="dev,local-test,re">
<appender name="sql" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>${LOG_PATH}/${myAppName}-sql.log</File>
<encoder>
<pattern>%d [%level] [%thread] %logger{15}:%line %msg%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${LOG_PATH}/${myAppName}-sql.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
<appender name="sql-queue" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>512</queueSize>
<appender-ref ref="sql"/>
</appender>
<!-- mybatis loggers -->
<logger name="dao" level="DEBUG" additivity="false">
<appender-ref ref="sql-queue"/>
</logger>
</springProfile>
复制代码
可以看到我们在dev,local-test,re 三个环境进行了日志的输出
2017-12-05 13:02:51,944 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll_COUNT:? ==> Preparing: SELECT count(0) FROM tb_user
2017-12-05 13:02:51,970 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll_COUNT:? ==> Parameters:
2017-12-05 13:02:51,984 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll_COUNT:? <== Total: 1
2017-12-05 13:02:51,988 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll:? ==> Preparing: SELECT pk_id,username,cell_phone,password,is_admin,id_role,creator,modifier,modifiedtime,creationtime,id_own_org,id_employee,is_del,is_guide_open,id_wxb_user,id_wxb_station,openid,limit_mac FROM tb_user limit ?,?
2017-12-05 13:02:51,994 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll:? ==> Parameters: 0(Integer), 10(Integer)
2017-12-05 13:02:52,008 [DEBUG] [XNIO-2 task-1] d.c.f.b.d.u.T.selectAll:? <== Total: 10
2017-12-05 13:03:34,582 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll_COUNT:? ==> Preparing: SELECT count(0) FROM tb_user
2017-12-05 13:03:34,582 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll_COUNT:? ==> Parameters:
2017-12-05 13:03:34,585 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll_COUNT:? <== Total: 1
2017-12-05 13:03:34,585 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll:? ==> Preparing: SELECT pk_id,username,cell_phone,password,is_admin,id_role,creator,modifier,modifiedtime,creationtime,id_own_org,id_employee,is_del,is_guide_open,id_wxb_user,id_wxb_station,openid,limit_mac FROM tb_user limit ?,?
2017-12-05 13:03:34,586 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll:? ==> Parameters: 0(Integer), 10(Integer)
2017-12-05 13:03:34,602 [DEBUG] [XNIO-2 task-2] d.c.f.b.d.u.T.selectAll:? <== Total: 10
复制代码
这样开发者就可以看到对应的sql
Druid日志
我们使用了druid作为db连接池 druid也提供了相关日志的输出
因此我们也可以通过druid的日志进行输出
我们在application.properties中可以定义如下
spring.datasource.initialSize=5
spring.datasource.minIdle=5
spring.datasource.maxActive=20
# 配置获取连接等待超时的时间
spring.datasource.maxWait=60000
# 配置间隔多久才进行一次检测,检测需要关闭的空闲连接,单位是毫秒
spring.datasource.timeBetweenEvictionRunsMillis=60000
# 配置一个连接在池中最小生存的时间,单位是毫秒
spring.datasource.minEvictableIdleTimeMillis=300000
spring.datasource.validationQuery=SELECT 1 FROM DUAL
spring.datasource.testWhileIdle=true
spring.datasource.testOnBorrow=false
spring.datasource.testOnReturn=false
# 打开PSCache,并且指定每个连接上PSCache的大小
spring.datasource.poolPreparedStatements=true
spring.datasource.maxPoolPreparedStatementPerConnectionSize=20
# 配置监控统计拦截的filters,去掉后监控界面sql无法统计,'wall'用于防火墙
spring.datasource.filters=stat,wall,slf4j
# 通过connectProperties属性来打开mergeSql功能;慢SQL记录
spring.datasource.connectionProperties=druid.stat.mergeSql=true;druid.stat.slowSqlMillis=5000
spring.datasource.useGlobalDataSourceStat=true
复制代码
注意在filter中存在slf4j
同样的道理找logback-spring中声明如下
<springProfile name="dev,local-test,re">
<appender name="druid" class="ch.qos.logback.core.rolling.RollingFileAppender">
<File>${LOG_PATH}/${myAppName}-druid.log</File>
<encoder>
<pattern>%d [%level] [%thread] %logger{15}:%line %msg%n</pattern>
</encoder>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>DEBUG</level>
</filter>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${LOG_PATH}/${myAppName}-druid.log.%d{yyyy-MM-dd}</fileNamePattern>
<maxHistory>30</maxHistory>
</rollingPolicy>
</appender>
<appender name="druid-queue" class="ch.qos.logback.classic.AsyncAppender">
<queueSize>512</queueSize>
<appender-ref ref="druid"/>
</appender>
<logger name="druid.sql.DataSource" level="DEBUG" additivity="false">
<appender-ref ref="druid-queue"/>
</logger>
<logger name="druid.sql.Connection" level="DEBUG" additivity="false">
<appender-ref ref="druid-queue"/>
</logger>
<logger name="druid.sql.Statement" level="DEBUG" additivity="false">
<appender-ref ref="druid-queue"/>
</logger>
</springProfile>
复制代码
这样也可以完成sql的输出
2017-12-05 13:02:42,665 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10001} connected
2017-12-05 13:02:42,680 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10002} connected
2017-12-05 13:02:42,694 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10003} connected
2017-12-05 13:02:42,712 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10004} connected
2017-12-05 13:02:42,724 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} connected
2017-12-05 13:02:42,764 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:02:42,776 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:02:42,847 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:02:42,940 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20000} created
2017-12-05 13:02:43,169 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20000, rs-50000} query executed. 224.655264 millis. SELECT 1 FROM DUAL
2017-12-05 13:02:43,174 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20000} closed
2017-12-05 13:02:43,174 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:02:43,175 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:02:43,175 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:02:43,175 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:02:43,175 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20001} created
2017-12-05 13:02:43,176 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20001, rs-50001} query executed. 1.123842 millis. SELECT 1 FROM DUAL
2017-12-05 13:02:43,176 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.sql.Statement:? {conn-10005, stmt-20001} closed
2017-12-05 13:02:43,176 [DEBUG] [RMI TCP Connection(11)-127.0.0.1] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:02:51,543 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:02:51,550 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10005} setAutoCommit false
2017-12-05 13:02:51,590 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10004} pool-connect
2017-12-05 13:02:51,590 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10004} pool-recycle
2017-12-05 13:02:51,958 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20002} created. SELECT count(0) FROM tb_user
2017-12-05 13:02:51,970 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20002} Parameters : []
2017-12-05 13:02:51,970 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20002} Types : []
2017-12-05 13:02:51,975 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20002} executed. 4.634146 millis. SELECT count(0) FROM tb_user
2017-12-05 13:02:51,992 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20003} created. SELECT pk_id,username,cell_phone,password,is_admin,id_role,creator,modifier,modifiedtime,creationtime,id_own_org,id_employee,is_del,is_guide_open,id_wxb_user,id_wxb_station,openid,limit_mac FROM tb_user limit ?,?
2017-12-05 13:02:51,994 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20003} Parameters : [0, 10]
2017-12-05 13:02:51,994 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20003} Types : [INTEGER, INTEGER]
2017-12-05 13:02:51,997 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20003} executed. 2.940797 millis. SELECT pk_id,username,cell_phone,password,is_admin,id_role,creator,modifier,modifiedtime,creationtime,id_own_org,id_employee,is_del,is_guide_open,id_wxb_user,id_wxb_station,openid,limit_mac FROM tb_user limit ?,?
2017-12-05 13:02:52,035 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20002} clearParameters.
2017-12-05 13:02:52,035 [DEBUG] [XNIO-2 task-1] d.sql.Statement:? {conn-10005, pstmt-20003} clearParameters.
2017-12-05 13:02:52,036 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10005} commited
2017-12-05 13:02:52,036 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10005} setAutoCommit true
2017-12-05 13:02:52,039 [DEBUG] [XNIO-2 task-1] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:03:34,570 [DEBUG] [XNIO-2 task-2] d.s.Connection:? {conn-10005} pool-connect
2017-12-05 13:03:34,573 [DEBUG] [XNIO-2 task-2] d.s.Connection:? {conn-10005} setAutoCommit false
2017-12-05 13:03:34,582 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20002} Parameters : []
2017-12-05 13:03:34,582 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20002} Types : []
2017-12-05 13:03:34,584 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20002} executed. 1.864303 millis. SELECT count(0) FROM tb_user
2017-12-05 13:03:34,586 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20003} Parameters : [0, 10]
2017-12-05 13:03:34,586 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20003} Types : [INTEGER, INTEGER]
2017-12-05 13:03:34,589 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20003} executed. 2.872636 millis. SELECT pk_id,username,cell_phone,password,is_admin,id_role,creator,modifier,modifiedtime,creationtime,id_own_org,id_employee,is_del,is_guide_open,id_wxb_user,id_wxb_station,openid,limit_mac FROM tb_user limit ?,?
2017-12-05 13:03:34,603 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20002} clearParameters.
2017-12-05 13:03:34,603 [DEBUG] [XNIO-2 task-2] d.sql.Statement:? {conn-10005, pstmt-20003} clearParameters.
2017-12-05 13:03:34,604 [DEBUG] [XNIO-2 task-2] d.s.Connection:? {conn-10005} commited
2017-12-05 13:03:34,604 [DEBUG] [XNIO-2 task-2] d.s.Connection:? {conn-10005} setAutoCommit true
2017-12-05 13:03:34,607 [DEBUG] [XNIO-2 task-2] d.s.Connection:? {conn-10005} pool-recycle
2017-12-05 13:06:00,780 [DEBUG] [Thread-80] d.s.Connection:? {conn-10001} closed
2017-12-05 13:06:00,781 [DEBUG] [Thread-80] d.s.Connection:? {conn-10002} closed
2017-12-05 13:06:00,781 [DEBUG] [Thread-80] d.s.Connection:? {conn-10003} closed
2017-12-05 13:06:00,782 [DEBUG] [Thread-80] d.s.Connection:? {conn-10004} closed
2017-12-05 13:06:00,782 [DEBUG] [Thread-80] d.sql.Statement:? {conn-10005, pstmt-20002} closed
2017-12-05 13:06:00,782 [DEBUG] [Thread-80] d.sql.Statement:? {conn-10005, pstmt-20003} closed
2017-12-05 13:06:00,782 [DEBUG] [Thread-80] d.s.Connection:? {conn-10005} closed
复制代码