TiDB AutoCommit OFF 问题

作者：TiDB 社区干货传送门

2022 年 7 月 11 日
本文字数：4432 字
阅读完需：约 15 分钟

作者： jiyf 原文来源：https://tidb.net/blog/f290fd55

【是否原创】是

【首发渠道】TiDB 社区

【首发渠道链接】其他平台首发请附上对应链接

【目录】

【正文】

复现问题

tiup cluster start XXXX
关闭自动提交
将 tidb server 日志设为 debug 级别，重启集群 tiup cluster stop XXXX; tiup cluster start XXXX;
登录到其中一个 tidb-server, 取名 tidb-M，在上面创建用户
使用新建用户 ‘jiyf’@’%’ 去登录 tidb-M，登录成功
使用新建用户 ‘jiyf’@’%’ 去登录另一个 tidb-server 取名 tidb-N，登录失败

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

等待 20 分钟，一般 gc 设置 10 分钟，这里等待 20 分钟是为了让 gc 的 safepoint 晚于 tidb 启动时间。
打开任意 tidb server 的日志，观察到以下报错
登录到 tidb server，查看 gc 相关信息

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

打开任意 tidb server 日志

观察到任意的 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]

复制代码

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

LoadPrivilegeLoop 函数中使用了全局变量的 autocommit = off
LoadPrivilegeLoop 第一个查询开启了事务，获取了 startts 为 2021-07-28 14:34:28.456 +0800 CST
由于没有显示的 commit/rollback，事务一直处于开启状态，startts 一直未变
由于 startts 较小，基于 mvcc 快照读，tidb-N 中 LoadPrivilegeLoop 没有查询到新建用户 ’jiyf’@’%’ 的信息，所以新用户的登录验证不通过
等启动 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 的流程：

tidb server 查询当前 gc leader 信息，如果当前 leader 为空，或者任期已满，那么竞选 leader.
竞选 gc leader，写入自己的信息以及 leader 任期
进行 gc 流程
由于 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 函数：

没有通过 begin/commit/rollback 开启使用事务
函数中通过 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"]

复制代码

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

tidb gc 模块调用 loadValueFromSysTable 查询 gc leader 的租期 lease 已经过期
注册自己为 gc leader，调用 saveValueToSysTable 写入自己的信息等
由于 saveValueToSysTable 未开启自动提交，导致事务被回滚，但是并没有任何报错，导致一直不知道写入不成功
开始进行 gc 的流程
把 safepoint 写入 etcd，tikv 拉取后进行 gc 回收旧数据
各个 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        }}