乐观事务模型下写写冲突问题排查

本文介绍 TiDB 中乐观锁下写写冲突出现的原因以及解决方案。

在 v3.0.8 版本之前,TiDB 默认采用乐观事务模型,在事务执行过程中并不会做冲突检测,而是在事务最终 COMMIT 提交时触发两阶段提交,并检测是否存在写写冲突。当出现写写冲突,并且开启了事务重试机制,则 TiDB 会在限定次数内进行重试,最终重试成功或者达到重试次数上限后,会给客户端返回结果。因此,如果 TiDB 集群中存在大量的写写冲突情况,容易导致集群的 Duration 比较高。

出现写写冲突的原因

TiDB 中使用 Percolator 事务模型来实现 TiDB 中的事务。Percolator 总体上就是一个二阶段提交的实现。具体的二阶段提交过程可参考乐观事务文档

当客户端发起 COMMIT 请求的时候,TiDB 开始两阶段提交:

  1. TiDB 从所有要写入的 Key 中选择一个作为当前事务的 Primary Key
  2. TiDB 向所有的本次提交涉及到的 TiKV 发起 prewrite 请求,TiKV 判断是否所有 Key 都可以 prewrite 成功
  3. TiDB 收到所有 Key 都 prewrite 成功的消息
  4. TiDB 向 PD 请求 commit_ts
  5. TiDB 向 Primary Key 发起第二阶段提交。Primary Key 所在的 TiKV 收到 commit 操作后,检查数据合法性,清理 prewrite 阶段留下的锁
  6. TiDB 收到两阶段提交成功的信息

写写冲突发生在 prewrite 阶段,当发现有其他的事务在写当前 Key (data.commit_ts > txn.start_ts),则会发生写写冲突。

TiDB 会根据 tidb_disable_txn_auto_retrytidb_retry_limit 参数设置的情况决定是否进行重试,如果设置了不重试,或者重试次数达到上限后还是没有 prewrite 成功,则向 TiDB 返回 Write Conflict 错误。

如何判断当前集群存在写写冲突

可以通过 Grafana 监控查看集群写写冲突的情况:

  • 通过 TiDB 监控面板中 KV Errors 监控栏中 KV Backoff OPS 监控指标项,查看 TiKV 中返回错误信息的数量

    kv-backoff-ops

    txnlock 表示集群中存在写写冲突,txnLockFast 表示集群中存在读写冲突。

  • 通过 TiDB 监控面板中 KV Errors 监控栏中 Lock Resolve OPS 监控指标项,查看事务冲突相关的数量

    lock-resolve-ops

    expired、not_expired、wait_expired 表示对应的 lock 状态

  • 通过 TiDB 监控面板中 KV Errors 监控栏中 KV Retry Duration 监控指标项,查看 KV 重试请求的时间

    kv-retry-duration

也可以通过 TiDB 日志查看是否有 [kv:9007]Write conflict 关键字,如果搜索到对应关键字,则可以表明集群中存在写写冲突。

如何解决写写冲突问题

如果通过以上方式判断出集群中存在大量的写写冲突,建议找到冲突的数据,以及写写冲突的原因,看是否能从应用程序修改逻辑,加上重试的逻辑。当出现写写冲突的时候,可以在 TiDB 日志中看到类似的日志:

[2020/05/12 15:17:01.568 +08:00] [WARN] [session.go:446] ["commit failed"] [conn=3] ["finished txn"="Txn{state=invalid}"] [error="[kv:9007]Write conflict, txnStartTS=416617006551793665, conflictStartTS=416617018650001409, conflictCommitTS=416617023093080065, key={tableID=47, indexID=1, indexValues={string, }} primary={tableID=47, indexID=1, indexValues={string, }} [try again later]"]

关于日志的解释如下:

  • [kv:9007]Write conflict:表示出现了写写冲突
  • txnStartTS=416617006551793665:表示当前事务的 start_ts 时间戳,可以通过 pd-ctl 工具将时间戳转换为具体时间
  • conflictStartTS=416617018650001409:表示冲突事务的 start_ts 时间戳,可以通过 pd-ctl 工具将时间戳转换为具体时间
  • conflictCommitTS=416617023093080065:表示冲突事务的 commit_ts 时间戳,可以通过 pd-ctl 工具将时间戳转换为具体时间
  • key={tableID=47, indexID=1, indexValues={string, }}:表示当前事务中冲突的数据,tableID 表示发生冲突的表的 ID,indexID 表示是索引数据发生了冲突。如果是数据发生了冲突,会打印 handle=x 表示对应哪行数据发生了冲突,indexValues 表示发生冲突的索引数据
  • primary={tableID=47, indexID=1, indexValues={string, }}:表示当前事务中的 Primary Key 信息

通过 pd-ctl 将时间戳转换为可读时间:

tiup ctl:<cluster-version> pd -u https://127.0.0.1:2379 tso {TIMESTAMP}

通过 tableID 查找具体的表名:

curl http://{TiDBIP}:10080/db-table/{tableID}

通过 indexID 查找具体的索引名:

SELECT * FROM INFORMATION_SCHEMA.TIDB_INDEXES WHERE TABLE_SCHEMA='{db_name}' AND TABLE_NAME='{table_name}' AND INDEX_ID={indexID};

另外在 v3.0.8 及之后版本默认使用悲观事务模式,从而避免在事务提交的时候因为冲突而导致失败,无需修改应用程序。悲观事务模式下会在每个 DML 语句执行的时候,加上悲观锁,用于防止其他事务修改相同 Key,从而保证在最后提交的 prewrite 阶段不会出现写写冲突的情况。