前言
没有看过前文的朋友，可以先去看看上次在笔者笔记本上做的尝试：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()
