需求
项目中遇到需要打印sql语句日志,还有其执行时间,还要把sql语句美化下(把 ?替换成实际的参数、换行符删除),目的在于打印sql语句时加入我们自己的日志关键字。比如说项目中集成了链路追踪功能,那么我们想打印sql 语句时,能如下输出:
span:xxxx, [SQL:......] 执行耗时 [.. ms]
这样如果我们有集成了es的话后期出问题查日志很方便,只要有这个链路id,我们就可以找到所有这个链路中执行的sql(异步除外)
这个肯定是用mybatis plugins没错了,但是具体sql 中的参数如何获取呢,这个需要看下源码,研究下mybatis 官方打印日志源码
源码分析
mybatis 官方如何打印日志?
先看看官方打印出的日志
我们一个个找,看看这个些日志都是怎么打印的
小编找源码就一种套路,debug!!一言不合就debug,但是呢这个debug得有技巧(日志等级得是debug!!!!),你得刚刚号打在日志打印之前,比如说 Preparing
日志打印之后,Parameters
日志打印之前,这里就得提到官方提供的插件机制
// Component 是在spring 中注入的不是官方写的
@Component
@Slf4j
@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 ExamplePlugin implements Interceptor {
private Properties properties = new Properties();
public Object intercept(Invocation invocation) throws Throwable {
// 在这里打断点~~~~~~~~~~~~~
Object returnObject = invocation.proceed();
// implement post processing if need
return returnObject;
}
public void setProperties(Properties properties) {
this.properties = properties;
}
}
这个其实是对 org.apache.ibatis.executor.statement.StatementHandler
实现了这个接口的类中的指定方法形成类似aop切面
打了断点之后
然后呢你就看到控制台就打印了一条Preparing
日志,这时候看下栈
嗯?没啥感觉?一开始我也不知道怎么查,结果看到 com.baomidou.mybatisplus.core.executor.MybatisSimpleExecutor#doQuery
@Override
public <E> List<E> doQuery(MappedStatement ms, Object parameter, RowBounds rowBounds, ResultHandler resultHandler, BoundSql boundSql) throws SQLException {
Statement stmt = null;
try {
Configuration configuration = ms.getConfiguration();
StatementHandler handler = configuration.newStatementHandler(wrapper, ms, parameter, rowBounds, resultHandler, boundSql);
//继续在这打断点
stmt = prepareStatement(handler, ms.getStatementLog(), false);
return stmt == null ? Collections.emptyList() : handler.query(stmt, resultHandler);
} finally {
closeStatement(stmt);
}
}
继续断点,com.baomidou.mybatisplus.core.executor.MybatisSimpleExecutor#prepareStatement
看到这个 connection
么,xxxLogger,还是代理类,只要你继续打断点在这,就知道 Preparing
日志在这之后打印的,那么这个类 org.apache.ibatis.logging.jdbc.ConnectionLogger
就很关键了
public final class ConnectionLogger extends BaseJdbcLogger implements InvocationHandler {
private final Connection connection;
private ConnectionLogger(Connection conn, Log statementLog, int queryStack) {
super(statementLog, queryStack);
this.connection = conn;
}
@Override
public Object invoke(Object proxy, Method method, Object[] params)
throws Throwable {
try {
if (Object.class.equals(method.getDeclaringClass())) {
return method.invoke(this, params);
}
if ("prepareStatement".equals(method.getName())) {
if (isDebugEnabled()) {
// 是不是很眼熟!!!!!!!!!!!
debug(" Preparing: " + removeBreakingWhitespace((String) params[0]), true);
}
PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
stmt = PreparedStatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else if ("prepareCall".equals(method.getName())) {
if (isDebugEnabled()) {
debug(" Preparing: " + removeBreakingWhitespace((String) params[0]), true);
}
PreparedStatement stmt = (PreparedStatement) method.invoke(connection, params);
stmt = PreparedStatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else if ("createStatement".equals(method.getName())) {
Statement stmt = (Statement) method.invoke(connection, params);
stmt = StatementLogger.newInstance(stmt, statementLog, queryStack);
return stmt;
} else {
return method.invoke(connection, params);
}
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
/**
* 代理对象生成
*/
public static Connection newInstance(Connection conn, Log statementLog, int queryStack) {
...
}
....
}
到这里 Preparing
日志找到了,这时候大家看这个结构,也能猜到了 org.apache.ibatis.logging.jdbc.BaseJdbcLogger
,看下有哪些类继承了这个
org.apache.ibatis.logging.jdbc.PreparedStatementLogger
/**
* 实现 InvocationHandler 接口,显然是一个代理对象
*/
public final class PreparedStatementLogger extends BaseJdbcLogger implements InvocationHandler {
private final PreparedStatement statement;
//真正执行的是 PreparedStatement
private PreparedStatementLogger(PreparedStatement stmt, Log statementLog, int queryStack) {
super(statementLog, queryStack);
this.statement = stmt;
}
@Override
public Object invoke(Object proxy, Method method, Object[] params) throws Throwable {
try {
.....
if (EXECUTE_METHODS.contains(method.getName())) {
if (isDebugEnabled()) {
// 打印参数,这里很关键
debug("Parameters: " + getParameterValueString(), true);
}
clearColumnInfo();
if ("executeQuery".equals(method.getName())) {
// 生成 ResultSet 代理对象 ResultSetLogger,打印 Total 日志
ResultSet rs = (ResultSet) method.invoke(statement, params);
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else {
return method.invoke(statement, params);
}
} else if (SET_METHODS.contains(method.getName())) {
if ("setNull".equals(method.getName())) {
setColumn(params[0], null);
} else {
setColumn(params[0], params[1]);
}
return method.invoke(statement, params);
} else if ("getResultSet".equals(method.getName())) {
ResultSet rs = (ResultSet) method.invoke(statement, params);
return rs == null ? null : ResultSetLogger.newInstance(rs, statementLog, queryStack);
} else if ("getUpdateCount".equals(method.getName())) {
int updateCount = (Integer) method.invoke(statement, params);
if (updateCount != -1) {
// 打印 Update 日志
debug(" Updates: " + updateCount, false);
}
return updateCount;
} else {
return method.invoke(statement, params);
}
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
/**
* jdk反射创建一个代理对象实例
*
*/
public static PreparedStatement newInstance(PreparedStatement stmt, Log statementLog, int queryStack) {
........
}
/**
* Return the wrapped prepared statement.
*
* @return the PreparedStatement
*/
public PreparedStatement getPreparedStatement() {
return statement;
}
}
实际上这就是一个代理对象,目的是在执行增删改查等sql时打印日志 Parameters
同理 ResultSetLogger
这个打印的就是 Total
日志。
这几个类像不像一条完整的链路,myabtis 执行sql,封装数据结果的链路
ConnectionLogger
sql 预加载,连接 mysql,打印的是 Preparing
PreparedStatementLogger
动态参数编译,打印的是 Parameters
ResultSetLogger
结果集处理,打印的是 Total
mybatis 官方如何打印参数?
根据上面的结果,同理在 org.apache.ibatis.logging.jdbc.PreparedStatementLogger#invoke
方法中打个断点,就能找到 com.baomidou.mybatisplus.core.MybatisDefaultParameterHandler#setParameters
public void setParameters(PreparedStatement ps) {
ErrorContext.instance().activity("setting parameters").object(mappedStatement.getParameterMap().getId());
List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
if (parameterMappings != null) {
for (int i = 0; i < parameterMappings.size(); i++) {
ParameterMapping parameterMapping = parameterMappings.get(i);
if (parameterMapping.getMode() != ParameterMode.OUT) {
Object value;
String propertyName = parameterMapping.getProperty();
if (boundSql.hasAdditionalParameter(propertyName)) { // issue #448 ask first for additional params
value = boundSql.getAdditionalParameter(propertyName);
} else if (parameterObject == null) {
value = null;
} else if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
value = parameterObject;
} else {
MetaObject metaObject = configuration.newMetaObject(parameterObject);
value = metaObject.getValue(propertyName);
}
TypeHandler typeHandler = parameterMapping.getTypeHandler();
JdbcType jdbcType = parameterMapping.getJdbcType();
if (value == null && jdbcType == null) {
jdbcType = configuration.getJdbcTypeForNull();
}
try {
typeHandler.setParameter(ps, i + 1, value, jdbcType);
} catch (TypeException | SQLException e) {
throw new TypeException("Could not set parameters for mapping: " + parameterMapping + ". Cause: " + e, e);
}
}
}
}
}
这样所有的sql 参数全部能拿到
代码实现
import lombok.extern.slf4j.Slf4j;
import org.apache.ibatis.binding.MapperMethod;
import org.apache.ibatis.executor.statement.StatementHandler;
import org.apache.ibatis.mapping.BoundSql;
import org.apache.ibatis.mapping.ParameterMapping;
import org.apache.ibatis.mapping.ParameterMode;
import org.apache.ibatis.plugin.*;
import org.apache.ibatis.reflection.MetaObject;
import org.apache.ibatis.session.Configuration;
import org.apache.ibatis.session.ResultHandler;
import org.apache.ibatis.session.SqlSessionFactory;
import org.apache.ibatis.session.defaults.DefaultSqlSession;
import org.apache.ibatis.type.TypeHandlerRegistry;
import java.lang.reflect.Field;
import java.sql.Statement;
import java.util.*;
/**
* Sql执行时间记录拦截器
*/
@Slf4j
@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 {
@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 {
printSqlLog(startTime, statementHandler);
}
}
/**
* 打印sql 日志
* @param startTime
* @param statementHandler
*/
public void printSqlLog(long startTime, StatementHandler statementHandler) {
long endTime = System.currentTimeMillis();
long sqlCost = endTime - startTime;
BoundSql boundSql = statementHandler.getBoundSql();
Object parameterObject = boundSql.getParameterObject();
String sql = boundSql.getSql();
// 格式化Sql语句,去除换行符,替换参数
// 推荐方案
String allSql = null;
try {
allSql = getFllSql(boundSql, parameterObject);
} catch (Exception e) {
log.warn("sql 格式化失败:{}", e.getMessage());
}
if (allSql == null) {
allSql = sql;
}
log.info("SQL:[" + allSql + "] 执行耗时 [" + sqlCost + "ms]");
// ActiveSpan.info("SQL:[" + allSql + "] 执行耗时 [" + sqlCost + "ms]");
}
@Override
public Object plugin(Object target) {
return Plugin.wrap(target, this);
}
@Override
public void setProperties(Properties properties) {
}
/**
* 获取完整的sql(推荐方案)
*/
public String getFllSql(BoundSql boundSql, Object parameterObject) {
// 从
SqlSessionFactory bean = SpringContext.getBean(SqlSessionFactory.class);
if (bean == null) {
return null;
}
Configuration configuration = bean.getConfiguration();
TypeHandlerRegistry typeHandlerRegistry = configuration.getTypeHandlerRegistry();
List<ParameterMapping> parameterMappings = boundSql.getParameterMappings();
if (CollectionUtil.isEmpty(parameterMappings)) {
return null;
}
List<Object> paramList = new ArrayList<>();
for (int i = 0; i < parameterMappings.size(); i++) {
ParameterMapping parameterMapping = parameterMappings.get(i);
if (parameterMapping.getMode() == ParameterMode.OUT) {
continue;
}
Object value = null;
String propertyName = parameterMapping.getProperty();
if (boundSql.hasAdditionalParameter(propertyName)) { // issue #448 ask first for additional params
value = boundSql.getAdditionalParameter(propertyName);
} else if (parameterObject == null) {
value = null;
} else if (typeHandlerRegistry.hasTypeHandler(parameterObject.getClass())) {
value = parameterObject;
} else {
MetaObject metaObject = configuration.newMetaObject(parameterObject);
value = metaObject.getValue(propertyName);
}
/*TypeHandler typeHandler = parameterMapping.getTypeHandler();
JdbcType jdbcType = parameterMapping.getJdbcType();
if (value == null && jdbcType == null) {
jdbcType = configuration.getJdbcTypeForNull();
}*/
paramList.add(value);
}
String sql = boundSql.getSql();
for (Object o : paramList) {
sql = sql.replaceFirst("\\?", formatParamValue(o));
}
return beautifySql(sql);
}
public String formatParamValue(Object paramValue) {
if (paramValue == null) {
return "null";
}
if (paramValue instanceof String) {
paramValue = "'" + paramValue + "'";
}
if (paramValue instanceof Date) {
paramValue = "'" + paramValue + "'";
}
return paramValue.toString();
}
}
SpringContext
@Component
public class SpringContext implements ApplicationContextAware {
private static ApplicationContext applicationContext;
@Override
public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {
SpringContext.applicationContext = applicationContext;
}
public static ApplicationContext getApplicationContext() {
return applicationContext;
}
public static Object getBean(String name) {
return applicationContext.getBean(name);
}
public static <T> T getBean(Class<T> clazz) {
try {
return applicationContext.getBean(clazz);
} catch (BeansException e) {
return null;
}
}
}
写在最后
遗憾的是total还没办法打印出来,如果有想法的小伙伴,下方留言评论谢谢了哈