SpringBoot结合LogBack打印Sql


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
复制代码

  • 0
    点赞
  • 2
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值