文章详细描述了一位开发者在遇到MyBatis批量插入操作性能问题后，如何通过编写MyBatis插件进行耗时分析，发现主要耗时在于PreparedStatement的update方法。经过进一步测试，定位到可能与数据库连接池（如Hikari和Druid）以及特定插件有关，指出日志输出也可能影响效率。最终，作者经过长时间追踪，发现问题出在一个用于处理OracleIN函数限制的插件上，该插件的字符串处理方式导致了性能下降。
MyBtais 批量插入慢排查及分析（后续）
前言
没有看过前文的朋友，可以先去看看上次在笔者笔记本上做的尝试：MyBatis痛点验证，使用 foreach 批量插入慢？
上次做的验证，因为无法复现生产场景，最终失败，这次我们来看后续进一步的验证与排查
一、同SQL以工程方式运行
我把上次在笔记本上的动态sql，移植到我们的工程代码里，放在一个普通查询接口里，进行usertest表的数据插入。而且一个方法内重复插好几次。
大家知道上次，我们的基准测试，一个对象的插入大约8ms
而同样插入一个对象，在工程里跑，大约需要 256ms ！！
当我不知死活的尝试插入2000条数据时，耗时直接到达270s，整整四分半！！
二、使用Plugin排查耗时情况
1. 编写mybatis plugin
代码如下：
@Component
@Intercepts({
@Signature(
type = ParameterHandler.class,
method = "setParameters",
args = { PreparedStatement.class }) ,
@Signature(
type = StatementHandler.class,
method = "prepare",
args = { Connection.class ,Integer.class}),
@Signature(
type = StatementHandler.class,
method = "update",
args = { Statement.class}),
@Signature(
type = Executor.class,
method = "update",
args = { MappedStatement.class ,Object.class}) ,})
@Slf4j
public class ParameterPlugin implements Interceptor {
@Override
public Object intercept(Invocation invocation) throws Throwable {
long start = System.currentTimeMillis();
String parameterHandlerName = invocation.getTarget().getClass().getName();
String statementName = invocation.getArgs()[0].getClass().getName();
String methodName = invocation.getMethod().getName();
Object returnVal = invocation.proceed();
long end = System.currentTimeMillis();
if ("prepare".equals(methodName)) {
log.info("StatementHandler.prepare耗时: " + (end - start) + ", 其中start =" + start + ", end =" + end);
}
if ("setParameters".equals(methodName)) {
log.info("参数装填时间" + (end - start) + ", 参数处理器类型为: " + parameterHandlerName + " ,statement类型为" + statementName
+ ", 其中start =" + start + ", end =" + end);
}
if ("update".equals(methodName)) {
log.info("update耗时: " + (end - start) + ", 其中start =" + start + ", end =" + end);
}
return returnVal;
}
}
上述的plugin 可以同时截取到几大组件的核心方法耗时，然后运行程序，反复以100为长度，进行耗时占比分析
2. 反复测试，分析结果
我原先预期，可能是参数填充的问题，但通过结果看，100*26=2600 个字段的填充耗时在10ms上下，这肯定是没问题的。耗时的大头是两个update方法，因为Executor的update是包含StatementHandler的update的，所以我们找到了耗时的最终方法，即StatementHandler的update.
因为这是动态sql，所以最后是由 PreparedStatementHandler 来处理的，我们关注一下该方法
@Override
public int update(Statement statement) throws SQLException {
PreparedStatement ps = (PreparedStatement) statement;
ps.execute();
int rows = ps.getUpdateCount();
Object parameterObject = boundSql.getParameterObject();
KeyGenerator keyGenerator = mappedStatement.getKeyGenerator();
keyGenerator.processAfter(executor, mappedStatement, ps, parameterObject);
return rows;
}
3. 进一步测试
既然已经确定了是在PreparedStatementHandler.update()里导致耗时太高的，那我们就想办法把日志打进去
先把plugin稍作改造，自定义个update，内容照抄，然后加点日志。
@Intercepts({
@Signature(
type = ParameterHandler.class,
method = "setParameters",
args = { PreparedStatement.class }) ,
@Signature(
type = StatementHandler.class,
method = "prepare",
args = { Connection.class ,Integer.class}),
@Signature(
type = StatementHandler.class,
method = "update",
args = { Statement.class})})
@Slf4j
public class ParameterPlugin implements Interceptor {
@Override
public Object intercept(Invocation invocation) throws Throwable {
String methodName = invocation.getMethod().getName();
if ("update".equals(methodName)) {
long time1 = System.currentTimeMillis();
PreparedStatement ps = (PreparedStatement) invocation.getArgs()[0];
long time2 = System.currentTimeMillis();
if (ps instanceof Proxy) {
InvocationHandler invocationHandler = Proxy.getInvocationHandler(ps);
log.info("invocationHandler = " + invocationHandler.getClass().getName());
if (invocationHandler instanceof PreparedStatementLogger) {
PreparedStatementLogger lo = (PreparedStatementLogger)invocationHandler;
PreparedStatement preparedStatement = lo.getPreparedStatement();
log.info("preparedStatement = " + preparedStatement.getClass().getName());
if (preparedStatement instanceof HikariProxyPreparedStatement) {
log.info("now in HikariProxyPreparedStatement");
}
}
}
ps.execute();
long time3 = System.currentTimeMillis();
int rows = ps.getUpdateCount();
long time4 = System.currentTimeMillis();
log.info("自定义update开始： time2-time1=" + (time2-time1) + ", time3-time2=" + (time3-time2) + ", time4-time3="+ (time4-time3));
return rows;
}
long start = System.currentTimeMillis();
String parameterHandlerName = invocation.getTarget().getClass().getName();
String statementName = invocation.getArgs()[0].getClass().getName();
Object returnVal = invocation.proceed();
long end = System.currentTimeMillis();
if ("prepare".equals(methodName)) {
log.info("StatementHandler.prepare耗时: " + (end - start) + ", 其中start =" + start + ", end =" + end);
}
if ("setParameters".equals(methodName)) {
log.info("参数装填时间" + (end - start) + ", 参数处理器类型为: " + parameterHandlerName + " ,statement类型为" + statementName
+ ", 其中start =" + start + ", end =" + end);
}
return returnVal;
}
}
然后在笔记本和开发工程上都进行100条数据的插入
- 笔记本DEMO上
- 环境项目上
从而进一步缩小范围，demo中用到了Hikari作为线程池，但项目上用的却是 Druid ？这其实有点奇怪，因为项目和demo使用的都是 springboot 2.5.x，按理来说，默认使用的都是Hikari。因此接下来的任务就是指定配置，使得项目可以使用Hikari 而非 Druid 。
三、总结
现在终于告一段落了，至于Druid 为什么会这么慢，还是有隐藏的设置导致的，后面还会继续追查，更新在这里。但无论如何，至少也证明了罪责不在mybatis上，mybatis的运行还是十分快的,2000行*26字段的数据，参数填充仅需119ms，符合纯计算的速度
另外，在测试过程中，发现mybatis的日志输出影响也很可观，如果有必要，关闭日志输出也能有不小的效率提升
四、长期更新进度
PS: 再次追查该问题，使用Arthas ,目前定位jdbc驱动发送执行语句sendCommand耗时很长，单条插入语句达到300ms，然后单看发送本身没问题，反而是收到执行结果后，后面的checkErrorMessage耗时太长
com.mysql.cj.protocol.a.NativeProtocol.readMessage()
五、最终结果
时隔一年之久，终于找到了问题的根因，即是项目中的一个mybatis插件导致的，这个插件是用来解决《Mybatis plugin 的使用及原理》 里面提到的·oracle·的 in 函数不能超过1000个元素的问题。
这个插件会直接生成一个可执行SQL，也就是说会把所有的 ？ 替换成其真正的值。
实现方式是使用for循环遍历，再用replaceFirst不停替换，这种字符串的处理导致非常慢。当然我是怎么发现的呢？其实也使用了很多方法和手段，最后发现还是JDK自己的工具最好用，使用的是visualVM排查出来的，具体步骤可参考添加链接描述
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
