TiDB AutoCommit OFF 问题

【是否原创】是
【首发渠道】TiDB 社区
【首发渠道链接】其他平台首发请附上对应链接
【目录】
【正文】

复现问题

  1. tiup cluster start XXXX
  2. 关闭自动提交
mysql> set global autocommit = 0;
Query OK, 0 rows affected (0.00 sec)
  1. 将 tidb server 日志设为 debug 级别,重启集群 tiup cluster stop XXXX; tiup cluster start XXXX;
  2. 登录到其中一个 tidb-server, 取名 tidb-M,在上面创建用户
mysql>  create user 'jiyf'@'%' identified by '123';
Query OK, 0 rows affected (0.05 sec)
  1. 使用新建用户 ‘jiyf’@’%’ 去登录 tidb-M,登录成功
  2. 使用新建用户 ‘jiyf’@’%’ 去登录另一个 tidb-server 取名 tidb-N,登录失败

这里就出现问题了,为什么新建的用户在 tidb-N 上登录验证不通过。

  1. 等待 20 分钟,一般 gc 设置 10 分钟,这里等待 20分钟是为了让 gc 的 safepoint 晚于 tidb 启动时间。
  2. 打开任意 tidb server 的日志,观察到以下报错
[2021/07/28 14:46:43.294 +08:00] [WARN] [cache.go:299] ["load mysql.user fail"] [error="[tikv:9006]GC life time is shorter than transaction duration, transaction starts at 2021-07-28 14:34:28.456 +0800 CST, GC safe point is 2021-07-28 14:35:28.556 +0800 CST"]
[2021/07/28 14:46:43.294 +08:00] [ERROR] [domain.go:941] ["load privilege failed"] [error="[privilege:8049]mysql.user"]
  1. 登录到 tidb server,查看 gc 相关信息
mysql> select VARIABLE_NAME,VARIABLE_VALUE from mysql.tidb where VARIABLE_NAME = "tikv_gc_leader_lease";
+----------------------+-------------------------+
| VARIABLE_NAME        | VARIABLE_VALUE          |
+----------------------+-------------------------+
| tikv_gc_leader_lease | 20210728-14:35:46 +0800 |
+----------------------+-------------------------+
1 row in set (0.00 sec)

mysql> select VARIABLE_NAME,VARIABLE_VALUE from mysql.tidb where VARIABLE_NAME = "tikv_gc_last_run_time";
+-----------------------+-------------------------+
| VARIABLE_NAME         | VARIABLE_VALUE          |
+-----------------------+-------------------------+
| tikv_gc_last_run_time | 20210728-14:24:46 +0800 |
+-----------------------+-------------------------+
1 row in set (0.00 sec)

mysql> select VARIABLE_NAME,VARIABLE_VALUE from mysql.tidb where VARIABLE_NAME = "tikv_gc_safe_point";
+--------------------+-------------------------+
| VARIABLE_NAME      | VARIABLE_VALUE          |
+--------------------+-------------------------+
| tikv_gc_safe_point | 20210728-14:14:46 +0800 |
+--------------------+-------------------------+
1 row in set (0.00 sec)

观察发现 gc 相关信息一值没有变化,而当前时间早已经过于 tikv_gc_leader_lease。

  1. 打开任意 tidb server 日志
[2021/07/28 15:09:17.873 +08:00] [DEBUG] [gc_worker.go:1818] ["[gc worker] load kv"] [key=tikv_gc_leader_uuid] [value=5ebade73e800002]
[2021/07/28 15:09:17.873 +08:00] [DEBUG] [txn.go:328] ["[kv] rollback txn"] [txnStartTS=426627867045003267]
[2021/07/28 15:09:17.873 +08:00] [DEBUG] [gc_worker.go:1676] ["[gc worker] got leader"] [uuid=5ebade73e800002]
[2021/07/28 15:09:17.873 +08:00] [DEBUG] [txn.go:328] ["[kv] rollback txn"] [txnStartTS=426627867045003266]
......
[2021/07/28 15:09:17.877 +08:00] [DEBUG] [gc_worker.go:1702] ["[gc worker] register as leader"] [uuid=5ebab090fb80009]
[2021/07/28 15:09:17.879 +08:00] [DEBUG] [gc_worker.go:1833] ["[gc worker] save kv"] [key=tikv_gc_leader_uuid] [value=5ebab090fb80009] []
[2021/07/28 15:09:17.879 +08:00] [DEBUG] [txn.go:328] ["[kv] rollback txn"] [txnStartTS=426627867045003270]

观察到任意的 tidb server 都在注册自己为 gc leader,并且开始进行 gc 过程,并且有奇怪的日志 rollback txn。

用户登录失败

在复现问题第 8 步中,观察到下面日志报错。

[2021/07/28 14:46:43.294 +08:00] [WARN] [cache.go:299] ["load mysql.user fail"] [error="[tikv:9006]GC life time is shorter than transaction duration, transaction starts at 2021-07-28 14:34:28.456 +0800 CST, GC safe point is 2021-07-28 14:35:28.556 +0800 CST"]
[2021/07/28 14:46:43.294 +08:00] [ERROR] [domain.go:941] ["load privilege failed"] [error="[privilege:8049]mysql.user"]

根据 ERROR 信息打开源代码文件,报错地方函数功能:定期的查询表同步集群中用户权限信息的。所以是不是同步用户权限这里失败导致 tidb-N 没有最新的权限信息,使得新用户验证不通过呢。

// LoadPrivilegeLoop create a goroutine loads privilege tables in a loop, it
// should be called only once in BootstrapSession.
func (do *Domain) LoadPrivilegeLoop(ctx sessionctx.Context) error {
	...
	err := do.privHandle.Update(ctx)
	...
	go func() {
		...
		for {
			...
			case <-time.After(duration):
			...
			err := do.privHandle.Update(ctx)
			...
			if err != nil {
				logutil.BgLogger().Error("load privilege failed", zap.Error(err))
			}
		...
	}()
	...
}

上面 warn 日志报错失败原因,事务 transaction starts 早于 GC safe point。为什么用了一个这么小的 startts 呢,观察到后面的报错,发现这个 startts 从来没有变化过,一直为 2021-07-28 14:34:28.456 +0800 CST。

[2021/07/28 15:26:43.310 +08:00] [WARN] [cache.go:299] ["load mysql.user fail"] [error="[tikv:9006]GC life time is shorter than transaction duration, transaction starts at 2021-07-28 14:34:28.456 +0800 CST, GC safe point is 2021-07-28 14:58:03.556 +0800 CST"]
[2021/07/28 15:26:43.311 +08:00] [ERROR] [domain.go:941] ["load privilege failed"] [error="[privilege:8049]mysql.user"]

在日志中搜索集群启动时间,搜索关键子 Welcome,查看到 tidb server 启动时间 2021/07/28 14:34:28.415,给上面的 startts 是同一个时间点,而 LoadPrivilegeLoop 函数就是启动时候开启调用的。

[2021/07/28 14:34:28.415 +08:00] [INFO] [printer.go:33] ["Welcome to TiDB."] ["Release Version"=v5.0.2] [Edition=Community] ["Git Commit Hash"=dc40a093a0058b95fc859f60d4b84337dbdff9f6] ["Git Branch"=heads/refs/tags/v5.0.2] 

联系到集群中关闭了自动提交,结合上面的点,推测下问题产生的原因:

  1. LoadPrivilegeLoop 函数中使用了全局变量的 autocommit = off
  2. LoadPrivilegeLoop 第一个查询开启了事务,获取了 startts 为 2021-07-28 14:34:28.456 +0800 CST
  3. 由于没有显示的 commit/rollback,事务一直处于开启状态,startts 一直未变
  4. 由于 startts 较小,基于 mvcc 快照读,tidb-N 中 LoadPrivilegeLoop 没有查询到新建用户 ’jiyf’@’%’ 的信息,所以新用户的登录验证不通过
  5. 等启动 20min 以后,由于 gc 的推进, safe point 已经大于 startts,开始上面的 ERROR 信息:“load privilege failed”。

为了验证这个假设在源码中加入两个日志信息,过滤的是 LoadPrivilegeLoop 调用的 sql,这里一条打印事务的 startts,一条验证 auto commit 是不是关闭状态。

        if strings.Contains(sql, "SELECT HIGH_PRIORITY Host,User,authentication_string,") {
                if s.txn.Valid() {
                        logutil.Logger(ctx).Info("txn start ts", zap.Uint64("txnStartTS", s.txn.StartTS()))
                } else {
                        logutil.Logger(ctx).Info("txn is not valid")
                }
                if s.sessionVars.IsAutocommit() {
                        logutil.Logger(ctx).Info("IsAutocommit")
                } else {
                        logutil.Logger(ctx).Info("not IsAutocommit")
                }
        }

运行后观察 tidb log,可以看到日志信息,确实是上面推测的情况。

[2021/07/28 16:13:11.639 +08:00] [INFO] [session.go:1249] ["txn start ts"] [txnStartTS=426628840569176071]
[2021/07/28 16:13:11.640 +08:00] [INFO] [session.go:1256] ["not IsAutocommit"]

修复

基于上面的问题排查结果,由于 LoadPrivilegeLoop 在 autocommit = on 情况下是没有问题的,那把它使用的 session 设置会话的 autocommit 设为 on 应该就能解决问题,添加以下代码:

_, err := ctx.(sqlexec.SQLExecutor).ExecuteInternal(context.Background(), "set @@autocommit = 1")

验证后用户登录问题就解决了。

GC 不正常

总结下上面 gc 不正常的点:

  • 在第 9 步中,查询到 mysql.tidb 表中 gc 相关的几个值,是没有变化的,好像 gc 没有在进行
  • 在第 10 步中,显示所有的 tidb server 都注册自己为 gc leader,而且都成功进行了 gc
  • 在第 8 步中显示 gc 是进行的,对比两条相似的日志,发现 tikv 的 gc safe point 在变大
  • 日志出现 gc 事务 ["[kv] rollback txn"]

补充下 tidb server 进行 gc 的流程:

  1. tidb server 查询当前 gc leader 信息,如果当前 leader 为空,或者任期已满,那么竞选 leader.
  2. 竞选 gc leader,写入自己的信息以及 leader 任期
  3. 进行 gc 流程
  4. 由于 tikv_gc_mode 是 distributed 模式,那么把 safepoint 写入 etcd,tikv 读取根据 safepoint 进行 gc.

根据第 10 步中的日志信息,查看 loadValueFromSysTable 函数:

func (w *GCWorker) loadValueFromSysTable(key string) (string, error) {
	ctx := context.Background()
	se := createSession(w.store)
	defer se.Close()
	rs, err := se.ExecuteInternal(ctx, `SELECT HIGH_PRIORITY (variable_value) FROM mysql.tidb WHERE variable_name=%? FOR UPDATE`, key)
	...
	logutil.BgLogger().Debug("[gc worker] load kv",
		zap.String("key", key),
		zap.String("value", value))
	return value, nil
}

发现 loadValueFromSysTable 函数:

  1. 没有通过 begin/commit/rollback 开启使用事务
  2. 函数中通过 defer se.Close() 来关闭新建的 session

这里如果使用的是 autocommit = 0,那么在执行 sql 后新会话 se 会开启一个事务,在函数退出时候 se.close() 关闭时候,会发现当前事务处于未结束状态,那么就会把它 rollback,从而会出现上面的日志。

[2021/07/28 15:09:17.873 +08:00] [DEBUG] [gc_worker.go:1818] ["[gc worker] load kv"] [key=tikv_gc_leader_uuid] [value=5ebade73e800002]
[2021/07/28 15:09:17.873 +08:00] [DEBUG] [txn.go:328] ["[kv] rollback txn"] 

对于 saveValueToSysTable 有着同样的逻辑:

func (w *GCWorker) saveValueToSysTable(key, value string) error {
	const stmt = `INSERT HIGH_PRIORITY INTO mysql.tidb VALUES (%?, %?, %?)
			       ON DUPLICATE KEY
			       UPDATE variable_value = %?, comment = %?`
	se := createSession(w.store)
	defer se.Close()
	_, err := se.ExecuteInternal(context.Background(), stmt,
		key, value, gcVariableComments[key],
		value, gcVariableComments[key])
	logutil.BgLogger().Debug("[gc worker] save kv",
		zap.String("key", key),
		zap.String("value", value),
		zap.Error(err))
	return errors.Trace(err)
}

对应以下日志部分:

[2021/07/28 15:09:17.879 +08:00] [DEBUG] [gc_worker.go:1833] ["[gc worker] save kv"] [key=tikv_gc_leader_uuid] [value=5ebab090fb80009] []
[2021/07/28 15:09:17.879 +08:00] [DEBUG] [txn.go:328] ["[kv] rollback txn"] 

基于以上推测整个问题流程如下:

  1. tidb gc 模块调用 loadValueFromSysTable 查询 gc leader 的租期 lease 已经过期
  2. 注册自己为 gc leader,调用 saveValueToSysTable 写入自己的信息等
  3. 由于 saveValueToSysTable 未开启自动提交,导致事务被回滚,但是并没有任何报错,导致一直不知道写入不成功
  4. 开始进行 gc 的流程
  5. 把 safepoint 写入 etcd,tikv 拉取后进行 gc 回收旧数据
  6. 各个 tidb server 重复上面这些流程

修复

跟用户登录失败一样的原因导致的问题,所以修复方法也类似。

上面测试的版本是 v5.0.2,从 githup 拉取最新源码编译测试,发现只有用户登录失败的问题,而没有这个 v5.0.2 gc 出现的问题。

对比后才发现这个问题刚不久前修复了:

func createSession(store kv.Storage) session.Session {
        for {
                se, err := session.CreateSession(store)
                if err != nil {
                        logutil.BgLogger().Warn("[gc worker] create session", zap.Error(err))
                        continue
                }
                // Disable privilege check for gc worker session.
                privilege.BindPrivilegeManager(se, nil)
                se.GetSessionVars().CommonGlobalLoaded = true
                se.GetSessionVars().InRestrictedSQL = true
                return se
        }
}

其中 se.GetSessionVars().CommonGlobalLoaded = true 就是修复方案:

  1. 创建 session 时候,默认的会话级别 autocommit 是 on 的
  2. session 执行 sql 时候,如果 CommonGlobalLoaded 是 false,那么就从全局变量加载变量信息
  3. 由于这里设置了 CommonGlobalLoaded = true,就不会从全局变量加载
  4. 那么 session 变量 autocommit 是 on
  5. 会进行自动提交,问题得到解决

修复问题的 issue 以及 pr:

https://github.com/pingcap/tidb/issues/24976

https://github.com/pingcap/tidb/pull/24975

1赞

前排学习~