likes
comments
collection
share

Troubleshooting系列-启动ShardingJDBC后首次查询慢问题分析及解决

作者站长头像
站长
· 阅读数 9

前言:之前使用shardingjdbc5.2版本作为客户端分库分表组件后,经开发同学反馈有个比较奇怪的问题。就是启动后首次SQL执行速度会比较慢,后面就正常。本文主要基于此问题进行重现和解决。

问题重现

新增CouponController用于调试

@RestController
@RequestMapping("/coupon")
public class CouponController {
    private static final Logger LOGGER = LoggerFactory.getLogger(CouponController.class);

    @Resource
    private CouponInfoMapper couponInfoMapper;

    @PostMapping(path = "/add")
    public void addCouponCode(CouponInfo couponInfo) {
        couponInfoMapper.addCouponCode(couponInfo);
    }

    @GetMapping(path = "/query")
    public List<CouponInfo> selectByCouponCode(String couponCode, String country) {
        long start = System.currentTimeMillis();
        List<CouponInfo> couponInfoList = couponInfoMapper.selectByCouponCode(couponCode, country);
        LOGGER.info("selectByCouponCode time={}", System.currentTimeMillis() - start);
        return couponInfoList;
    }
}

在浏览器执行两次调用请求后

http://localhost:8088/h/coupon/query?couponCode=1234&country=CN

日志如下,第一次964ms,第二次6ms

Troubleshooting系列-启动ShardingJDBC后首次查询慢问题分析及解决

分析定位

定位这种耗时问题可以采用阿里开源的Java诊断工具 Arthas(阿尔萨斯)

安装启动非常便捷

curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar

启动后执行命令,在期间执行两次命令

[arthas@2111]$ profiler start
Profiling started
[arthas@2111]$ profiler stop --format html
OK
profiler output file: /home/toby/dynamic/bin/arthas-output/20231022-204409.html
[arthas@2111]$

获得火焰图结果

Troubleshooting系列-启动ShardingJDBC后首次查询慢问题分析及解决

分析如下方法在执行较慢

org/apache/shardingsphere/driver/jdbc/core/connection/ShardingSphereConnection.prepareStatement
org/apache/calcite/rel/rules/CoreRules.<clinit>

org/apache/shardingsphere/infra/parser/ShardingSphereSQLParserEngine.parse
org/apache/shardingsphere/sql/parser/core/SQLParserFactory.newInstance
org/apache/shardingsphere/sql/parser/core/SQLParserFactory.createSQLParser和java/lang/reflect/Constructor.newInstance

分析CoreRules,发现其主要是静态类的加载,应该只会执行一次

public class CoreRules {

  private CoreRules() {}

  /** Rule that recognizes an {@link Aggregate}
   * on top of a {@link Project} and if possible
   * aggregates through the Project or removes the Project. */
  public static final AggregateProjectMergeRule AGGREGATE_PROJECT_MERGE =
      AggregateProjectMergeRule.Config.DEFAULT.toRule();

  /** Rule that removes constant keys from an {@link Aggregate}. */
  public static final AggregateProjectPullUpConstantsRule
      AGGREGATE_PROJECT_PULL_UP_CONSTANTS =
      AggregateProjectPullUpConstantsRule.Config.DEFAULT.toRule();

分析SQLParserFactory.newInstance,最终会执行到反射相关代码,应该也是执行一次就好了

public static SQLParser newInstance(final String sql, final Class<? extends SQLLexer> lexerClass, final Class<? extends SQLParser> parserClass) {
    return createSQLParser(createTokenStream(sql, lexerClass), parserClass);
}
private static ReflectionFactory getReflectionFactory() {
    if (reflectionFactory == null) {
        reflectionFactory =
            java.security.AccessController.doPrivileged
                (new sun.reflect.ReflectionFactory.GetReflectionFactoryAction());
    }
    return reflectionFactory;
}

分析到这里后,发现第一次执行SQL,会经历很多的预加载,分析基本上都是一次性的,sharding还有执行sql相关的缓存,不过从分析结果来看,不是影响执行耗时的主要原因。

解决措施

可以在系统启动后,自动执行一个查询sql自动预加载上述比较耗时的操作,这样真正的业务SQL进来后,就不会很慢了。具体的代码如下:

@Component
public class ShardingPreLoadService implements InitializingBean {
    private static final Logger LOGGER = LoggerFactory.getLogger(ShardingPreLoadService.class);
    @Resource
    private DataSource dataSource;

    @Override
    public void afterPropertiesSet() throws Exception {
        Connection connection = dataSource.getConnection();
        String sql = "select 1";
        connection.prepareStatement(sql).execute();
        LOGGER.info("ShardingPreLoadService load end.");
    }
}

Troubleshooting系列-启动ShardingJDBC后首次查询慢问题分析及解决

优化后,第一次调用167ms,比之前900多优化很多。第二次执行6ms因为有sharding执行计划缓存、MYSQL本身buffer优化,这块是不好优化到6ms这么少的。

转载自:https://juejin.cn/post/7292437487012855818
评论
请登录