一次慢查詢暴露的隱蔽問題

程式通事發表於2019-01-05

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 除錯日誌

從日誌中我們可以清楚看到實際執行的 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 執行計劃如下。

慢 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。

DateTypeHandler

然後我們檢視 Oracle JDBC 資料型別轉換規則。在 docs.oracle.com/cd/B19306_0… 我們可以看到，TIMESTAMP 將轉換成 Oracle 中 TIMESTAMP。

Oracle type

問題擴充套件

假設我們將 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 索引欄位上使用相關函式會導致慢查詢，查詢時切勿在索引欄位上使用函式。

參考文件

1、oracle 資料轉換
2.、oracle 時間型別

如果覺得好的話，請幫作者點個讚唄~ 謝謝

喜歡本文的讀者們，歡迎長按關注訂閱號程式通事~讓我與你分享程式那些事。

一次慢查詢暴露的隱蔽問題

推薦閱讀：
1、 生產系統 SQL 執行異常原因分析
2、 在 dubbo 中使用 Threadlocal 的相關問題
3、 從原始碼學習設計模式之模板方法

相關文章