TiDB new feature max_execution_time

作者：mantuliu​

max_execution_time的作用

據說max_execution_time是mysql5.7.8(沒有實際的驗證過)提供的一個feature，能夠有效地控制慢查詢，尤其對于資料庫性能要求比較高的業務場景非常有用。我在mysql和TiDB的生産環境下，之前都遇到過因為慢查詢消耗過多的機器資源，進而影響生産環境可用性的情況：

• mysql遇到問題的場景是：我們豐巢的一個基礎服務采用的mycat分庫分表，有個字段是字元串類型，但是開發小哥哥在查詢資料的時候傳的值是數值，造成索引失效，進而全表掃描。當時對于io等資源消耗非常嚴重，直接影響了生産環境的使用；
• TiDB的問題也是一樣的，如果column是字元串，但傳的值是數值類型，它的執行計劃會不斷的讀取TiKV的傳回值并在TiDB做運算cast，當時我們用的是千兆網卡，網絡直接打滿；

雖然我們豐巢針對生産環境的資料庫做了很多的限制，但總是難免會出現類似于上面提到的問題。在我們之前使用的TiDB版本(2.1.4)是沒有max_execution_time這個特性的，當時我們為了防止上面的問題再次出現，還專門的寫了一個TiDB的監控子產品，當出現高消耗的慢sql時，監控程式可以直接kill tidb session來完成。現在有了max_execution_time，一切都變得簡單了，我們可以在系統變量的級别來設定max_execution_time的值，進而限定了query sql的最大執行毫秒數，避免災難的發生。

TiDB max_execution_time初見

我記得TiDB在2.1的某一個小版本裡面便引入了max_execution_time的hint文法，但那時沒有實際的作用，看release的介紹，max_execution_time可以在實際環境中使用，是在2.1.14版本才開始的。如圖：

​​

​​

global 變量方式測試

我隻進行了global級别的系統變量的測試，沒有測試hint的方式，因為hint的方式在我們豐巢使用的機率比較低，兩方面的原因：一是hint的對于sql的改動較大；二是很難完成所有的sql添加此hint，一旦出現漏網之魚并且出了問題，那前面做的工作都沒有啥意義。測試的準備環境如下：

• TiDB版本 2.1.15
• TiDB節點數量：3
• TiDB開啟binlog服務pump
• TiKV節點數量：12(3台實體機，每台4個執行個體)
• PD情況：與TiDB、pump服務部署在相同的3台實體機上，3個節點
• 硬體條件：全部是SSD的磁盤
• 負載均衡：nginx1.17.1+stream

測試用例

我的測試用例都比較簡單，首先使用資料同步工具和豐巢自研的流量錄制和實時回放工具，将生産環境的實際資料實時同步到測試環境，單表最大行數在幾十億這個級别。主要是想測試3種實際的情況：

• 變量max_execution_time的測試：多次設定global max_execution_time 的值，測試它在不同session的情況下是否實時生效；
• 測試在TiDB端和TiKV端都有大量計算的查詢語句情況，這個測試用例比較容易就可以實作，就用上面說的那個把網絡打滿的生産問題用例即可，使用傳遞的值為數字，但是列為字元串的sql語句，像這樣：select user_id,user_name from test where user_name = 18612345678;
• 測試計算主要是在TiKV端執行的語句，其中列user_content沒有索引：select user_id,user_name,user_content from test where user_content = ‘123456’;

測試結果

變量實時生效結果測試

我在一開始測試的時候，變量在1秒和10秒之間來回設定，如下：

set GLOBAL MAX_EXECUTION_TIME = 10000 //10秒
set GLOBAL MAX_EXECUTION_TIME = 1000 //1秒      

發現我在把最大執行時間從1秒切到10秒時，query被中斷的時間卻還是1秒。經過深入的分析，發現是global和session級别的原因，當我們設定了global的變量後，已經啟動的session實際用到的變量值，還是之前的session變量值，也就是舊值。這個時候，如果我們重新打開一個session，MAX_EXECUTION_TIME是生效的，也就是說新的session會讀取最新的global變量的值。那麼，這裡就需要我們在實際的生産環境使用的時候要注意，因為大部分的生産環境都是使用的長連接配接，session很長時間都不會被關閉的，因為和我們的預期值不一緻，很有可能會帶來生産問題。關于TiDB和mysql的session和global的詳細細節，我也沒有深入了解過，後面有時間會對這塊做個分析，我覺得類似于MAX_EXECUTION_TIME這種變量，最好是隻有global和hint兩種級别，否則很容易帶來了解上的混淆以及潛在的生産環境問題。我猜測TiDB這樣做，是為了要相容mysql的原因。

TiDB端和TiKV端都有大量計算測試結果

首先設定MAX_EXECUTION_TIME為10秒

set GLOBAL MAX_EXECUTION_TIME = 10000      

再啟動一個新的連接配接，執行類似于下面的語句，user_name為字元串類型變量，test表行數有一億以上的資料

select user_id,user_name from test where user_name = 18612345678;      

測試結果為

> 1317 - Query execution was interrupted
> 時間: 12.31s      

從結果上看，此種慢查詢的語句，在超過最大執行時間後，是可以被TiDB正常的結束掉的。

計算主要是在TiKV端執行的語句測試結果

這個測試用例的目的是想看看，計算已經下推導TiKV上的query語句，能不能在超過最大執行時間後正常的結束掉，還是在逾時時間為10秒的情況下，執行下面的語句，如前面說的，user_content是沒有索引的

select user_id,user_name,user_content  from test where user_content = '123456';      

測試結果如下：

> OK
> 時間: 75.91s      

測試結果說明，TiDB是無法正常結束這種計算都是在TiKV上做的語句的，在TiDB判斷了逾時時間過後，是無法通知到TiKV去結束掉這次計算的，隻能等待TiKV傳回結果後，再做決定。

源碼分析

大家有興趣，可以跟随這個PR，Add support for MAX_EXECUTION_TIME​，去詳細的分析源碼，在這裡我們來簡單的看一下相關的源碼。TiDB裡面有一個processinfo的存儲空間，主要是存儲所有session的目前執行sql的情況，我之前還寫過一篇源碼分析show processlist的源碼裡面有講到過processinfo的情況。

• 首先我們來看看max_execution_time是如何存儲到processinfo中的：

maxExecutionTime := getMaxExecutionTime(sctx, a.StmtNode)
    // Update processinfo, ShowProcess() will use it.
    pi.SetProcessInfo(sql, time.Now(), cmd, maxExecutionTime)
    a.Ctx.GetSessionVars().StmtCtx.StmtType = GetStmtLabel(a.StmtNode)      

代碼在adapter.go的Exec方法中，主要就是在sql執行前，先擷取max_execution_time的實際值，然後存到目前session的processinfo存儲空間裡面。

• getMaxExecutionTime 那麼maxExecutionTime的具體值的到底是怎麼來的呢？當hint和session同時存在時，優先級是如何計算的呢？

func getMaxExecutionTime(sctx sessionctx.Context, stmtNode ast.StmtNode) uint64 {
  ret := sctx.GetSessionVars().MaxExecutionTime
  if sel, ok := stmtNode.(*ast.SelectStmt); ok {
    for _, hint := range sel.TableHints {
      if hint.HintName.L == variable.MaxExecutionTime {
        ret = hint.MaxExecutionTime
        break
      }
    }
  }
  return ret
}      

由上面的代碼可知，hint的優先級會高于session的優先級，這也符合我們正常的思維方式。

• 如何kill掉逾時的query 最後我們來看看，TiDB是如何判斷query逾時了，并kill掉它的，在expensivequery.go中有一個goroutine會不斷的check，主要邏輯如下：

for {
    select {
    case <-ticker.C:
      processInfo := eqh.sm.ShowProcessList()
      for _, info := range processInfo {
        if info.Info == nil || info.ExceedExpensiveTimeThresh {
          continue
        }
        costTime := time.Since(info.Time)
        if costTime >= time.Second*time.Duration(threshold) && log.GetLevel() <= zapcore.WarnLevel {
          logExpensiveQuery(costTime, info)
          info.ExceedExpensiveTimeThresh = true

        } else if info.MaxExecutionTime > 0 && costTime > time.Duration(info.MaxExecutionTime)*time.Millisecond {
          eqh.sm.Kill(info.ID, true)
        }
      }
      threshold = atomic.LoadUint64(&variable.ExpensiveQueryTimeThreshold)
    case <-eqh.exitCh:
      return
    }
  }      

這個goroutine會通過ShowProcessList不斷的讀取目前正在執行的sql語句，并判斷costTime是否已經超過了之前設定到processinfo中的MaxExecutionTime，如果超過了，則kill掉這條query。其中的time.Millisecond 也表明了MaxExecutionTime的機關是毫秒。

最後