一次慢查询暴露的隐蔽问题

Photo by Iga Palacz on Unsplash

最近解决了一个生产 SQL 慢查询的问题，排查问题以后发现一些比较隐匿且容易忽略的问题。

业务背景介绍

最近业务上须要上线一个预警功能，须要查出一段时间内交易，求出当前交易成功率。当成功率低于设定阈值时，短信预警。业务逻辑很简单，测试环境测试也没问题以后，部署上线。实际生产运行时却发现每次 SQL 查询须要花费 60 多秒。

系统架构介绍

Spring boot + Mybatis + Oracle。

须要查询的表数量级为亿级。

排查问题

交易表结构(已经简化)大体以下。

create table TB_TEST
(
  BANK_CODE   VARCHAR2(20),
  CREATE_TIME DATE,
  OID_BILL    NUMBER(16) not null
)
/
create index TB_TEST_CREATE_TIME_INDEX
  on TB_TEST (CREATE_TIME)
/

create unique index TB_TEST_OID_BILL_UINDEX
  on TB_TEST (OID_BILL)
/

alter table TB_TEST
  add constraint TB_TEST_PK
    primary key (OID_BILL)
/

复制代码

该项目的增删改查语句使用 MybatisGenerate 自动生成，查询语句使用 CREATE_TIME 作为条件查询，自动生成 sql 以下。

select *
from TB_TEST
where CREATE_TIME >= #{start_time}
  and CREATE_TIME < #{end_time};

复制代码

咱们经过设置 Druid 的配置，将具体查询 SQL 日志输出到控制台。具体设置以下。

<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
  	... ...
  	<property name="filters" value="stat,slf4j" />
  </bean>

  <!-- logback -->
    <logger name="druid.sql.Statement" level="DEBUG" additivity="false">
        <appender-ref ref="STDOUT"/>
    </logger>
复制代码

具体 sql 日志以下：

从日志中咱们能够清楚看到实际运行的 SQL，以及查询参数与类型。

从查询语句看来，咱们查询条件正确，且因为 CREATE_TIME 存在独立索引，因此查询会走索引，查询速度应该很快，不至于每次查询须要花费 60 多秒。

因此当时猜想此次查询因为某些缘由发生了全表扫描，未走索引才致使慢查询。在 Google 搜索相关资料，看见一篇文章 www.cnblogs.com/chen--biao/…。

根据文章描述的是 Oracle 中存在隐式转换的状况，当类型不匹配的时，Oracle 会主动将类型转换成目标类型。查看咱们表结构，CREATE_TIME 为 Date 类型，而根据日志咱们查询参数传递的 CREATE_TIME 却为 TIMESTAMP 类型。

因此实际在数据库查询 SQL 以下：

SELECT *
FROM TB_TEST
WHERE (CREATE_TIME >= to_timestamp('2018-03-03 18:45:32', 'yyyy-mm-dd hh24:mi:ss') and
       CREATE_TIME < to_timestamp('2019-01-03 18:45:32', 'yyyy-mm-dd hh24:mi:ss'));

复制代码

可能这里发生一次隐式转换。

如何证实这个猜测那？咱们能够使用 EXPLAIN PLAN ，分析 SQL 执行计划.上面 SQL 执行计划以下。

从上图咱们能够从 TB ACCESS FULL 看出，此次查询慢确实因为是全表扫描致使。

而后咱们查看执行计划中的 Predicate Information 信息，Oracle 使用 INTERNAL_FUNCATIPON 转换 CREATE_TIME 类型 。从这点那能够看出查询过程索引字段发生一次内联函数转换。

SQL 性能优化每每会有一点，避免在索引字段使用函数。

既然知道缘由，那么解决办法也没有这么难了。咱们将查询 sql 改成以下就能解决。

select *
from TB_TEST
where CREATE_TIME >= TO_DATE(#{start_time}, 'yyyy-mm-dd hh24:mi:ss')
  and CREATE_TIME < TO_DATE(#{end_time}, 'yyyy-mm-dd hh24:mi:ss');

-- 或者使用 cast 函数
select *
from TB_TEST
where CREATE_TIME >= cast(#{start_time} as date)
  and CREATE_TIME < cast(#{end_time} as date);
复制代码

分析缘由

解决完问题，咱们分析下 Java 类型中的 Date 类型为何最终会转换成 Oracle 中的 TIMESTAMP 类型。

此次案例中咱们使用 Mybatis 框架，框架内部会将 Java 数据类型转换成对应的 JDBC 数据类型。查看Mybatis 类型转换 这一节咱们能够发现 Java Date 类型将会转换成 java.sql.TIMESTAMP。

而后咱们查看 Oracle JDBC 数据类型转换规则。在 docs.oracle.com/cd/B19306_0… 咱们能够看到，TIMESTAMP 将转换成 Oracle 中 TIMESTAMP。

问题扩展

假设咱们将 CREATE_TIME 类型修改为 TIMESTAMP，而后查询的时候将 CREATE_TIME 转换成 Date 类型，是否也会发生内联函数转换，而后致使全表扫描那？查询 sql 以下。

-- CREATE_TIME 类型为 TIMESTAMP
select *
from TB_TEST
where CREATE_TIME >= TO_DATE('2018-02-27 19:36:21', 'yyyy-mm-dd hh24:mi:ss')
  and CREATE_TIME < TO_DATE('2018-12-27 19:36:21', 'yyyy-mm-dd hh24:mi:ss')

复制代码

。。。。

。。。。

。。。。

咱们用 EXPLAIN PLAN 分析这个 SQL。

咱们能够看到，确实发生了一次内联转化，可是却在另一边。此次查询走的是索引。

从这个例子咱们能够看出，在索引字段上使用函数会致使全表扫描。可是在传入查询参数上使用函数并不会致使索引失效。

总结

1 SQL 查询时须要注意两边数据类型的一致性，虽然数据库隐式转换会帮咱们解决数据不一致的问题，可是这种隐式转化带来一些隐蔽问题，让咱们第一时间并不能很快发现。因此使用显示转换代替隐式转换。这样咱们的 SQL 清晰易懂，并且更加可控。

2 学会使用 EXPLAIN PLAN 分析慢 SQL。

3 索引字段上使用相关函数会致使慢查询，查询时切勿在索引字段上使用函数。

参考文档

一、oracle 数据转换
2.、oracle 时间类型

---

若是以为好的话，请帮做者点个赞呗~ 谢谢

喜欢本文的读者们，欢迎长按关注订阅号程序通事~让我与你分享程序那些事。

---

推荐阅读：
一、 生产系统 SQL 执行异常缘由分析
二、 在 dubbo 中使用 Threadlocal 的相关问题
三、 从源码学习设计模式之模板方法