Mybatis-Plus执行超长SQL性能问题排查

问题描述

项目上使用了Mybatis-Plus，发现部分接口性能很差，经常会超过30s导致响应超时。接口里边有很大的一个SQL，里边in条件塞了上千个user_id，本以为是这个sql导致的性能问题，后来发现SQL执行只花了几十ms。排查了几天终于发现了问题。

问题原因

我们使用了Mybatis-Plus的租户拦截器TenantLineInnerInterceptor，在SQL语句上自动拼接了tenant_id、appBuId这两个查询条件。排查发现，mapper接口对应的SQL如果很长，TenantLineInnerInterceptor拦截器拼接租户id的查询条件会有很严重的性能问题，SQL本身执行只需要几十毫秒，但拼接这个租户id的查询条件花了6、700ms；因为我们定义了两个TenantLineInnerInterceptor拦截器，所以一条SQL拼接查询条件，至少要1s多。最后使用Mybatis-Plus自带的@InterceptorIgnore注解，忽略租户Id的拦截器，自行组装查询条件，就不会有性能问题了。

排查过程

1. 一开始认为是in条件里边参数太多，导致性能太差。后来发现sql语句执行其实很快，说明不是这个原因。
2. 猜测是打印日志太长引起的，
   1. 关闭mybatis、mybatis-plus日志打印，控制台还是输出了
   2. 替换为mybatis最原始的数据源配置，不用动态数据源了，日志就不输出了，说明是打印日志是动态数据源的打印的
   3. 但接口耗时还是很长
3. 猜测是mybatis或者mybatis-plus预编译SQL，传入的in条件的参数太多，替换?占位符太多导致耗时长。
   1. 使用JDBC执行写死的SQL，速度正常；
   2. 新写了一个mapper方法，不传入参数，SQL语句也写死，不需要组装in条件的参数
   3. mapper方法耗时还是很长，使用了hutool的StopWatch来计算方法耗时
4. 不清楚是Mybatis还是Mybatis-Plus的问题，于是我创建了一个新项目，里边只引用了Mybatis，也是mapper方法也是写死SQL，发现执行耗时是正常的。
5. 那就确认是Mybatis-Plus的问题了，猜测是mybatis-plus的拦截器插件引起的，项目上使用了3个插件，乐观锁、分页、多租户插件，其中多租户使用了两次。
   1. 把mybatis拦截器里边逐个拦截器注释，看看mapper方法耗时；发现租户ID和appBuId的拦截器，注释掉后性能正常了，每多一个，耗时多600ms；到此定位到问题了。
6. 由于项目是SaaS系统，这个租户id拦截器是必须要加的，而且大部分SQL都没有性能问题，只有少数这几个in条件参数太多耗时长的问题。在Mybatis-Plus官网上找到了忽略拦截器的注解，加上之后，SQL耗时就正常了
7. 排查Mybatis-Plus源码，使用Arthas查看方法内部调用路径，并输出方法路径上的每个节点上耗时，MybatisPlusInterceptor是所有插件的核心。trace com.baomidou.mybatisplus.extension.plugins.MybatisPlusInterceptor intercept，可以看到主要耗时在beforeQuery方法上。trace com.baomidou.mybatisplus.extension.plugins.inner.TenantLineInnerInterceptor beforeQuery最后排查到是一个工具类JSqlParserUtil的parse方法耗时太长，这个来自于jsqlparser的第三方jar包，也不是Mybatis-Plus的代码，这块代码看不懂，就不再深究下去了……

总结 

Mybatis-Plus的租户拦截器，在遇到超长SQL的时候，拼接租户id的查询条件会有性能问题，这种场景可以单独使用 @InterceptorIgnore拦截忽略注解，忽略租户id的拼接，然后自行在SQL上添加这个租户id的查询条件，接口性能就正常了。