线上Bug! Sharing-JDBC第一次查询为什么这么慢?

一、缘起

内部框架发布了新版本，有开发反馈Sharding查询慢。通过一系列对比分析之后解决了问题。本文复盘排查过程，欢迎大家拍砖。（为了面子，本文摒弃了个人所犯低级错误，勿怪）

二、追踪

1、问题复现

@Test
publicvoid testInserts() {
Random random = new Random();

ArrayList<User> users = new ArrayList<>();
for(int i = 0; i < 400; i++) {
User user = newUser();
user.setId(random.nextInt());
user.setAge(20);
user.setName("bin");
users.add(user);
}
//Spring提供的计时器，非常简单好用，推荐使用
StopWatch stopWatch = new StopWatch();
//开始计时
stopWatch.start();
userMapper3.inserts(users);
//结束计时
stopWatch.stop();
//输出：总的用时
System.out.println("testInsert 共计："+ (stopWatch.getTotalTimeMillis()) + " ms");
}

执行结果：

[11-16 16:36:10.010] [WARN] [cat] Cat is lazy initialized! testInsert 共计：4826 ms

仅插入400条测试数据用了4秒多！

2、问题追踪

1）github Issues 寻找线索

简单分析之后，猜测是不源码问题。先去Issues搜下，果然搜到了线索！！

问题：使用sharding插入1万条数据花费了10秒多的时间。

官方解释：

第一次执行需要进行sql解析，再次将不需要花费这部分时间。也就是说第一次1万条数据需要10秒是正常的。

具体链接:github batch insert Issues
https://github.com/apache/incubator-shardingsphere/issues/3351

2）对比分析

(1）对比一条语句执行两次的时间消耗

@Test
publicvoid testInserts() {
Random random = new Random();
ArrayList<User> users = new ArrayList<>();
for(int i = 0; i < 400; i++) {
User user = newUser();
user.setId(random.nextInt());
user.setAge(20);
user.setName("bin");
users.add(user);
}
//Spring提供的计时器，非常简单好用，推荐使用
StopWatch stopWatch = new StopWatch();
//开始计时
stopWatch.start();
userMapper3.inserts(users);
//结束计时
stopWatch.stop();
//输出：总的用时
System.out.println("testInsert 共计："+ (stopWatch.getTotalTimeMillis()) + " ms");
StopWatch stopWatch2 = new StopWatch();
stopWatch2.start();
userMapper3.inserts(users)
stopWatch2.stop();
System.out.println("testInsert 共计："+ (stopWatch2.getTotalTimeMillis()) + " ms");
}

执行结果：

[11-16 14:39:20.020] [WARN] [cat] Cat is lazy initialized! testInsert 共计：4342 ms testInsert 共计：50 ms

第二次执行确实性能有巨大提升，这符合预期。

(2）第一次执行，花费时间太多，有问题。

现状：插入400条数据 4秒多，按照这个比例，插入一万条需要100秒。

显然：这与前面提到的1万条10秒差太多！！

使用JProfiler性能分析工具执行： JProfiler快速入门 https://blog.csdn.net/D_19901719576/article/details/103100056

通过JProfiler CPU view,监控调用链，观察到，时间主要消耗在熔断和Cat日志记录逻辑。

考虑到第一次执行时，相关组件都需要各自进行初始化【热加载？】。因此， 第一次执行慢是正常的 ，后续处理性能不会受到影响。

3、源码分析

Sql只在第一次执行需要解析，显然框架内部进行了缓存。

这个缓存在哪做的？

Mybatis核心 MapperProxy#invoke

@Override
public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
if (Object.class.equals(method.getDeclaringClass())) {
try {
return method.invoke(this, args);
} catch (Throwable t) {
throw ExceptionUtil.unwrapThrowable(t);
}
}
//调用 mapperMethod（）
final MapperMethod mapperMethod = cachedMapperMethod(method);
//执行sql
return mapperMethod.execute(sqlSession, args);
}
//缓存mapperMethod方法
private MapperMethod cachedMapperMethod(Method method) {
MapperMethod mapperMethod = methodCache.get(method);
//第一次执行时缓存
if (mapperMethod == null) {
mapperMethod = new MapperMethod(mapperInterface, method, sqlSession.getConfiguration());
methodCache.put(method, mapperMethod);
}
//直接返回缓存中的mapperMethod，无需重复解析，提升了性能。(ps:此时不需要sql解析)
return mapperMethod;
}

当我们使用Mapper进行数据库相关操作时会执行MapperProxy的invoke()方法。

invoke方法中会生成MapperMethod (ps:其中保存了mapper接口和所执行方法的对应关系)

通过mapperMethod#execute执行sql。

三、总结

1、Sharding执行三大核心，Sql解析->Sql改写-> Sql路由 -> Sql执行，解析操作只在第一次执行。

2、Sharding与Mybatis的结合使用，主流程依然在JDBC操作。Sharding源码主流程。 https://blog.csdn.net/D_19901719576/article/details/102874853

3、关于Mybatis接口核心原理可查看MapperFactoryFactoryhttps://blog.csdn.net/D_19901719576/article/details/98373254#2_MapperFactoryBean_195

附SharingJDBC简介：

Sharding-JDBC defines itself as a lightweight Java framework that provides extra service at Java JDBC layer. With the client end connecting directly to the database, it provides service in the form of jar and requires no extra deployment and dependence. It can be considered as an enhanced JDBC driver, which is fully compatible with JDBC and all kinds of ORM frameworks.

Applicable in any ORM framework based on JDBC, such as JPA, Hibernate, Mybatis, Spring JDBC Template or direct use of JDBC.
Support any third-party database connection pool, such as DBCP, C3P0, BoneCP, Druid, HikariCP.
Support any kind of JDBC standard database: MySQL, Oracle, SQLServer, PostgreSQL and any SQL92 followed databases.