TiDB new feature max_execution_time

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

最后

我个人觉得这个feature对于高并发的交易型业务是非常有必要的,它是可以作为一个最后的兜底策略。希望PingCap公司后面能在TiKV层面也能支持这个feature,真正的将风险降到最低,我本人对于TiDB是充满了无限期待的,希望它能越来越NB。

3赞

很赞的文章!