【是否原创】是
【首发渠道】TiDB 社区
【首发渠道链接】其他平台首发请附上对应链接
【目录】
【正文】
复现问题
- tiup cluster start XXXX
- 关闭自动提交
mysql> set global autocommit = 0;
Query OK, 0 rows affected (0.00 sec)
- 将 tidb server 日志设为 debug 级别，重启集群 tiup cluster stop XXXX; tiup cluster start XXXX;
- 登录到其中一个 tidb-server, 取名 tidb-M，在上面创建用户
mysql> create user 'jiyf'@'%' identified by '123';
Query OK, 0 rows affected (0.05 sec)
- 使用新建用户 ‘jiyf’@’%’ 去登录 tidb-M，登录成功
- 使用新建用户 ‘jiyf’@’%’ 去登录另一个 tidb-server 取名 tidb-N，登录失败
这里就出现问题了，为什么新建的用户在 tidb-N 上登录验证不通过。
- 等待 20 分钟，一般 gc 设置 10 分钟，这里等待 20分钟是为了让 gc 的 safepoint 晚于 tidb 启动时间。
- 打开任意 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"]
- 登录到 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。
- 打开任意 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]
联系到集群中关闭了自动提交，结合上面的点，推测下问题产生的原因：
- 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
}
}
其中 se.GetSessionVars().CommonGlobalLoaded = true 就是修复方案：
- 创建 session 时候，默认的会话级别 autocommit 是 on 的
- session 执行 sql 时候，如果 CommonGlobalLoaded 是 false，那么就从全局变量加载变量信息
- 由于这里设置了 CommonGlobalLoaded = true，就不会从全局变量加载
- 那么 session 变量 autocommit 是 on
- 会进行自动提交，问题得到解决
修复问题的 issue 以及 pr: