MyBtais 批量插入慢排查及分析（后续）

2023-07-21 110

版权

本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《阿里云开发者社区用户服务协议》和《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。

简介： 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;
    }
}