说实话，日志难看，在排查问题时会不爽。

线上出现问题，经常需要看数据库里面的数据有没有问题，是不是sql查询的时候就查错了，所以需要查看sql语句的日志，但是mybatis打印的日志都是占位符，还有很多换行符，非常不友好，druid默认的statementLogEnabled参数配置也有这个问题。

一开始为了解决这个痛点，没想到druid有提供可以打印可执行的sql的配置，功夫花在mybatis插件开发上，代码基于仓颉大佬博客中提到的内容，解决了使用参数值代替占位符时，实际参数字段有可能是ParameterObject的父类的这种情况，无法打印可执行SQL的问题，

Myabtis插件优化SQL语句输出

通过Myabtis插件优化SQL语句输出，具体代码如下：

import org.apache.ibatis.executor.statement.StatementHandler;
import org.apache.ibatis.mapping.BoundSql;
import org.apache.ibatis.mapping.ParameterMapping;
import org.apache.ibatis.plugin.*;
import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.session.defaults.DefaultSqlSession.StrictMap;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import java.lang.reflect.Field;
import java.sql.Statement;
import java.util.Collection;
import java.util.List;
import java.util.Map;
import java.util.Properties;

/**
 * Sql执行时间记录拦截器
 */
@Intercepts({@Signature(type = StatementHandler.class, method = "query", args = {Statement.class, ResultHandler.class}),
        @Signature(type = StatementHandler.class, method = "update", args = {Statement.class}),
        @Signature(type = StatementHandler.class, method = "batch", args = { Statement.class })})
public class SqlCostInterceptor implements Interceptor {
    private static final Logger logger = LoggerFactory.getLogger(SqlCostInterceptor.class);

    @Override
    public Object intercept(Invocation invocation) throws Throwable {
        Object target = invocation.getTarget();

        long startTime = System.currentTimeMillis();
        StatementHandler statementHandler = (StatementHandler)target;
        try {
            return invocation.proceed();
        } finally {
            long endTime = System.currentTimeMillis();
            long sqlCost = endTime - startTime;

            BoundSql boundSql = statementHandler.getBoundSql();
            String sql = boundSql.getSql();
            Object parameterObject = boundSql.getParameterObject();
            List<ParameterMapping> parameterMappingList = boundSql.getParameterMappings();

            // 格式化Sql语句，去除换行符，替换参数
            sql = formatSql(sql, parameterObject, parameterMappingList);

            logger.info("SQL：[" + sql + "]执行耗时[" + sqlCost + "ms]");
        }
    }

    @Override
    public Object plugin(Object target) {
        return Plugin.wrap(target, this);
    }

    @Override
    public void setProperties(Properties properties) {

    }

    @SuppressWarnings("unchecked")
    private String formatSql(String sql, Object parameterObject, List<ParameterMapping> parameterMappingList) {
        // 输入sql字符串空判断
        if (sql == null || sql.length() == 0) {
            return "";
        }

        // 美化sql
        sql = beautifySql(sql);

        // 不传参数的场景，直接把Sql美化一下返回出去
        if (parameterObject == null || parameterMappingList == null || parameterMappingList.size() == 0) {
            return sql;
        }

        // 定义一个没有替换过占位符的sql，用于出异常时返回
        String sqlWithoutReplacePlaceholder = sql;

        try {
            if (parameterMappingList != null) {
                Class<?> parameterObjectClass = parameterObject.getClass();

                // 如果参数是StrictMap且Value类型为Collection，获取key="list"的属性，这里主要是为了处理<foreach>循环时传入List这种参数的占位符替换
                // 例如select * from xxx where id in <foreach collection="list">...</foreach>
                if (isStrictMap(parameterObjectClass)) {
                    StrictMap<Collection<?>> strictMap = (StrictMap<Collection<?>>)parameterObject;

                    if (isList(strictMap.get("list").getClass())) {
                        sql = handleListParameter(sql, strictMap.get("list"));
                    }
                } else if (isMap(parameterObjectClass)) {
                    // 如果参数是Map则直接强转，通过map.get(key)方法获取真正的属性值
                    // 这里主要是为了处理<insert>、<delete>、<update>、<select>时传入parameterType为map的场景
                    Map<?, ?> paramMap = (Map<?, ?>) parameterObject;
                    sql = handleMapParameter(sql, paramMap, parameterMappingList);
                } else {
                    // 通用场景，比如传的是一个自定义的对象或者八种基本数据类型之一或者String
                    sql = handleCommonParameter(sql, parameterMappingList, parameterObjectClass, parameterObject);
                }
            }
        } catch (Exception e) {
            // 占位符替换过程中出现异常，则返回没有替换过占位符但是格式美化过的sql，这样至少保证sql语句比BoundSql中的sql更好看
            return sqlWithoutReplacePlaceholder;
        }

        return sql;
    }

    /**
     * 美化Sql
     */
    private String beautifySql(String sql) {
        // sql = sql.replace("\n", "").replace("\t", "").replace("  ", " ").replace("( ", "(").replace(" )", ")").replace(" ,", ",");
        sql = sql.replaceAll("[\\s\n ]+"," ");
        return sql;
    }

    /**
     * 处理参数为List的场景
     */
    private String handleListParameter(String sql, Collection<?> col) {
        if (col != null && col.size() != 0) {
            for (Object obj : col) {
                String value = null;
                Class<?> objClass = obj.getClass();

                // 只处理基本数据类型、基本数据类型的包装类、String这三种
                // 如果是复合类型也是可以的，不过复杂点且这种场景较少，写代码的时候要判断一下要拿到的是复合类型中的哪个属性
                if (isPrimitiveOrPrimitiveWrapper(objClass)) {
                    value = obj.toString();
                } else if (objClass.isAssignableFrom(String.class)) {
                    value = "\"" + obj.toString() + "\"";
                }

                sql = sql.replaceFirst("\\?", value);
            }
        }

        return sql;
    }

    /**
     * 处理参数为Map的场景
     */
    private String handleMapParameter(String sql, Map<?, ?> paramMap, List<ParameterMapping> parameterMappingList) {
        for (ParameterMapping parameterMapping : parameterMappingList) {
            Object propertyName = parameterMapping.getProperty();
            Object propertyValue = paramMap.get(propertyName);
            if (propertyValue != null) {
                if (propertyValue.getClass().isAssignableFrom(String.class)) {
                    propertyValue = "\"" + propertyValue + "\"";
                }

                sql = sql.replaceFirst("\\?", propertyValue.toString());
            }
        }

        return sql;
    }

    /**
     * 处理通用的场景
     */
    private String handleCommonParameter(String sql, List<ParameterMapping> parameterMappingList, Class<?> parameterObjectClass,
                                         Object parameterObject) throws Exception {
        for (ParameterMapping parameterMapping : parameterMappingList) {
            String propertyValue = null;
            // 基本数据类型或者基本数据类型的包装类，直接toString即可获取其真正的参数值，其余直接取paramterMapping中的property属性即可
            if (isPrimitiveOrPrimitiveWrapper(parameterObjectClass)) {
                propertyValue = parameterObject.toString();
            } else {
                String propertyName = parameterMapping.getProperty();
                Field field = null;
                try{
                    field = parameterObjectClass.getDeclaredField(propertyName);
                }catch (NoSuchFieldException e){
                    //如果当前类或者父类是Object，快速抛出错误
                    if(parameterObjectClass.isAssignableFrom(Object.class)
                            || parameterObjectClass.getSuperclass().isAssignableFrom(Object.class)){
                        throw e;
                    }
                    field = getField(parameterObjectClass, propertyName, field);
                }
                // 要获取Field中的属性值，这里必须将私有属性的accessible设置为true
                field.setAccessible(true);
                propertyValue = String.valueOf(field.get(parameterObject));
                if (parameterMapping.getJavaType().isAssignableFrom(String.class)) {
                    propertyValue = "\"" + propertyValue + "\"";
                }
            }

            sql = sql.replaceFirst("\\?", propertyValue);
        }

        return sql;
    }

    //处理当propertyName是parameterObjectClass的父类时不生效的情况
    private Field getField(Class<?> parameterObjectClass, String propertyName, Field field) throws NoSuchFieldException {
        //获取当前类的父类
        Class superClass = parameterObjectClass.getSuperclass();
        if(superClass.isAssignableFrom(Object.class)){
            throw new NoSuchFieldException();
        }
        //遍历父类的字段
        for(Field f : superClass.getDeclaredFields()){
            if(f.getName().equals(propertyName)){
                //如果父类的属性名找到了，赋值给field，结束循环，返回field
                field = f;
                break;
            }
        }
        if(field == null){
            //如果循环父类没有找到，递归调用当前方法，直到找到为止,找到顶级父类Object还是找不到，会抛出NoSuchFieldException
            getField(superClass,propertyName,field);
        }
        return field;
    }

    /**
     * 是否基本数据类型或者基本数据类型的包装类
     */
    private boolean isPrimitiveOrPrimitiveWrapper(Class<?> parameterObjectClass) {
        return parameterObjectClass.isPrimitive() ||
                (parameterObjectClass.isAssignableFrom(Byte.class) || parameterObjectClass.isAssignableFrom(Short.class) ||
                        parameterObjectClass.isAssignableFrom(Integer.class) || parameterObjectClass.isAssignableFrom(Long.class) ||
                        parameterObjectClass.isAssignableFrom(Double.class) || parameterObjectClass.isAssignableFrom(Float.class) ||
                        parameterObjectClass.isAssignableFrom(Character.class) || parameterObjectClass.isAssignableFrom(Boolean.class));
    }

    /**
     * 是否DefaultSqlSession的内部类StrictMap
     */
    private boolean isStrictMap(Class<?> parameterObjectClass) {
        return parameterObjectClass.isAssignableFrom(StrictMap.class);
    }

    /**
     * 是否List的实现类
     */
    private boolean isList(Class<?> clazz) {
        Class<?>[] interfaceClasses = clazz.getInterfaces();
        for (Class<?> interfaceClass : interfaceClasses) {
            if (interfaceClass.isAssignableFrom(List.class)) {
                return true;
            }
        }

        return false;
    }

    /**
     * 是否Map的实现类
     */
    private boolean isMap(Class<?> parameterObjectClass) {
        Class<?>[] interfaceClasses = parameterObjectClass.getInterfaces();
        for (Class<?> interfaceClass : interfaceClasses) {
            if (interfaceClass.isAssignableFrom(Map.class)) {
                return true;
            }
        }

        return false;
    }

    /**
     * 获取对象中的字段
     * @param obj which object you want to find filed
     * @param fieldName the field name you want to find
     * @return the field you want tofind
     * @throws Throwable
     * @throws NoSuchFieldException
     */
    protected Field getField(Object obj,String fieldName) throws NoSuchFieldException {
        Class clzz = obj.getClass();
        Field[] fields = clzz.getDeclaredFields();
        Field dest = null;
        while (!hasField(fields,fieldName) && !clzz.getName().equalsIgnoreCase("java.lang.Object")) {
            clzz = clzz.getSuperclass();
            fields = clzz.getDeclaredFields();
        }
        if (hasField(fields,fieldName)) {
            dest = clzz.getDeclaredField(fieldName);
        } else {
            throw new NoSuchFieldException("类中没有此字段");
        }

        return dest;
    }
    /**
     * 判断对象中是否有要找的字段
     * @param fields the fields which you want to find
     * @param fieldName the field name you want to find
     * @return if the field in field return true else return false
     */
    private boolean hasField(Field[] fields, String fieldName) {
        for (int i = 0; i < fields.length ;i ++) {
            if (fields[i].getName().equals(fieldName)) {
                return true;
            }
        }
        return false;
    }

}

烦人的问题：为什么会有两条带占位符的SQL语句

当我写的插件可以打印可执行SQL后，看到在可执行SQL前后，还是会有带占位符的SQL语句打印（原来项目中的），即现在系统里，执行一条SQL语句，会打印两条带占位符的语句，和一条可执行SQL语句，总共打印三条SQL语句。

为什么会有两条带占位符的SQL语句？？？通过后面对Druid源码的分析。默认druid的statementLogEnabled参数是true，如果配置了log4j的filter，在sql执行的时候会打印一条带占位符的SQL，在SQL执行完，druid又会打印一次带占位符的SQL。

Druid的SQL打印逻辑

Druid的SQL打印逻辑所在的类如下：

FilterEventAdapter类中：

 LogFilter类中：

第一次配置修改

那两条占位符的SQL对我们看日志来说没什么用，于是想着怎么过滤掉不显示，根据官网wiki的提示，加了如下配置：

<bean id="log-filter" class="com.alibaba.druid.filter.logging.Log4jFilter">
	<property name="resultSetLogEnabled" value="false" />
	<property name="statementLogEnabled" value="false"/>
	<property name="statementExecuteAfterLogEnabled" value="false"/>
	<property name="statementExecutableSqlLogEnable" value="true"/>
</bean>

 将过滤器加到数据源配置中：

<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource"
	init-method="init" destroy-method="close">
	省略其他属性配置
	<property name="proxyFilters">
		<list>
			<ref bean="log-filter"/>
		</list>
	</property>	
</bean>

将mybatis插件注释掉，不需要用了：

这样启动项目后，每次执行一条SQL，还是会打印两条带占位符和一条可执行的SQL语句，那一条可执行的SQL语句说明druid的statementExecutableSqlLogEnable配置生效了，但是为什么还是会打印两条带占位符的？

数据源中的原配置搞的鬼

先直接看为什么，因为数据源配置中配置了这个：

<property name="filters" value="stat,log4j,config" />

配置了三个过滤器，其中一个就是log4j。。。。

stat是监控，config是为了数据库加密

在debug追源码发现，DruidDataSource中的filter是4个，两个Log4jFilter：

两个Log4j，一个是上面的默认配置，一个是自定义的log4j配置。

最终配置修改：

所以解决方法就是把默认的配置去掉就可以了：

<property name="filters" value="stat,config" />

目前的SQl日志可以看了。

如果遇到线上问题需要排查，直接复制到plsql中执行就行了，不用替换占位符了。

总结：

1、这次的问题解决，首先自己关注了下项目中对于开发不友好的部分，SQL打印难看，给定位问题带来一些不便。

2、在解决这个问题的时候，主要资源是官网wiki和源码。在之前花了很多时间分析过Spring源码、Mybatis源码等后，分析Druid源码还是很轻松的。源码中找到的答案是最真实的。

3、debug能力更加巩固了，依然确信，源码分析没有捷径，就是自己debug，网上的分析的都是别人的，不是自己的，两个效果不一样。

4、准备有时间把Druid源码的运行逻辑和一些思路记录下，毕竟花了宝贵的时间，放脑子里保质期太短，不利于总结提炼。（****）

5、项目中的日志打印，除了SQL，其他的还是很乱，后续继续优化。（****）

6、打算专门写一篇，Druid中责任链模式的应用。（*****）

延伸阅读：

DruidDataSource源码解析

这篇文章一开始在介绍字段属性，然后我就没看了，发现自己debug找答案更快。但是等我回头看这篇文章，还是有很多共鸣的，总之可以参考，但是一定要先自己debug看源码。

作者的其他文章看起来也不错，日后闲暇翻阅