天天看点
返回

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版本才开始的。如图：

​​

TiDB new feature max_execution_time

​​

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的单位是毫秒。

最后

生产环境 sql mysql
上一篇: jdk定时任务TimerScheduledExecutorService
下一篇: Springboot自带定时任务

继续阅读