悲观锁 pessimistic write conflict 日志问题

🪐 TiDB 技术问题 部署&运维管理
1

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

  • 【TiDB 版本】：
    v4.0.6
  • 【问题描述】：
[2020/09/28 14:51:06.127 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251053] [txn=419764860631384268] [forUpdateTS=419764860644491269] [err="[kv:9007]Write conflict, txnStartTS=419764860631384268, conflictStartTS=419764860631384232, conflictCommitTS=419764860644491323, key={tableID=4269, handle=121240} primary={tableID=4289, indexID=1, indexValues={170556951598516173, }} [try again later]"]
[2020/09/28 14:51:06.168 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251125] [txn=419764860644491416] [forUpdateTS=419764860644491449] [err="[kv:9007]Write conflict, txnStartTS=419764860644491416, conflictStartTS=419764860644491357, conflictCommitTS=419764860657598515, key={tableID=4269, handle=121214} primary={tableID=4289, indexID=1, indexValues={170556951665625037, }} [try again later]"]
[2020/09/28 14:51:06.188 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251246] [txn=419764860657598504] [forUpdateTS=419764860657598521] [err="[kv:9007]Write conflict, txnStartTS=419764860657598504, conflictStartTS=419764860644491460, conflictCommitTS=419764860657598602, key={tableID=4269, handle=151206} primary={tableID=4289, indexID=1, indexValues={170556951699179469, }} [try again later]"]
[2020/09/28 14:51:06.538 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251125] [txn=419764860736241878] [forUpdateTS=419764860749348885] [err="[kv:9007]Write conflict, txnStartTS=419764860736241878, conflictStartTS=419764860736241871, conflictCommitTS=419764860749348942, key={tableID=4269, handle=121168} primary={tableID=4289, indexID=1, indexValues={170556952269604813, }} [try again later]"]
[2020/09/28 14:51:06.772 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251151] [txn=419764860801777898] [forUpdateTS=419764860801777965] [err="[kv:9007]Write conflict, txnStartTS=419764860801777898, conflictStartTS=419764860801777810, conflictCommitTS=419764860814884932, key={tableID=4269, handle=121178} primary={tableID=4289, indexID=1, indexValues={170556952672257997, }} [try again later]"]
[2020/09/28 14:51:06.939 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251246] [txn=419764860854206543] [forUpdateTS=419764860854206564] [err="[kv:9007]Write conflict, txnStartTS=419764860854206543, conflictStartTS=419764860854206468, conflictCommitTS=419764860854206606, key={tableID=4269, handle=121294} primary={tableID=4289, indexID=1, indexValues={170556952957536205, }} [try again later]"]
[2020/09/28 14:51:07.008 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251053] [txn=419764860867313840] [forUpdateTS=419764860867313845] [err="[kv:9007]Write conflict, txnStartTS=419764860867313840, conflictStartTS=419764860867313784, conflictCommitTS=419764860867313866, key={tableID=4269, handle=121276} primary={tableID=4289, indexID=1, indexValues={170556953074911181, }} [try again later]"]
[2020/09/28 14:51:07.183 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251151] [txn=419764860906635543] [forUpdateTS=419764860919742516] [err="[kv:9007]Write conflict, txnStartTS=419764860906635543, conflictStartTS=419764860906635457, conflictCommitTS=419764860919742616, key={tableID=4269, handle=121188} primary={tableID=4289, indexID=1, indexValues={170556953343346637, }} [try again later]"]
[2020/09/28 14:51:08.270 +08:00] [INFO] [adapter.go:611] ["pessimistic write conflict, retry statement"] [conn=251151] [txn=419764861168779418] [forUpdateTS=419764861168779436] [err="[kv:9007]Write conflict, txnStartTS=419764861168779418, conflictStartTS=419764861168779307, conflictCommitTS=419764861208100873, key={tableID=4269, handle=151188} primary={tableID=4289, indexID=1, indexValues={170556954987513805, }} [try again later]"]

日志信息描述有点疑惑

key={tableID=4269, handle=121178} primary={tableID=4289, indexID=1, indexValues={170556952672257997, }}

从业务角度讲，可能是 tableId=4289 报错了，但为何有个提示 key={tableID=4269, handle=121178} ？

实际业务场景中，并不存在主键 170556952672257997 冲突的情况，查日志也没发现有重复的情况出现。

造成这部分的原因大概什么情况呢？（该表预计写入 qps [40,60), 几乎无查询）

2

image
image1345×272 29 KB

3

文档确实这么说，但本身一堆 insert，写冲突的原因比较奇怪呀

4

key={tableID=4269, handle=151188} 表示冲突的 rowid 是 151188，如果表上有 int 类型的主键，那么主键就是 rowid，可以查一下对应的 information_schema.tables 的 TIDB_TABLE_ID 确认哪张表

后面 primary={tableID=4289, indexID=1, indexValues={170556952672257997, } 对应的 tableID 是指事务中的 primary key 对应的 tableID, 这个 primary key 是指 percolate 事务模型二阶段提交的时候会有一个 primary key ，如果事务中有更新多个表，会有 tableID 跟前面的 tableID 不一致的情况

5

那么按照这个解释，发生冲突的 table 是 4269，而非 4289，只是恰好本事务中操作了两张表，才会出现类似的日志。(该理解如有错误，请纠正)

业务关系： 4269 状态表，为更新操作，4289 数据表，为写入操作。

table_4269 操作伪代码如下：

begin
update x set v=1 where c1=1 and c2=2;
update x set v=2 where c1=1 and c2=3;
commit;

再请教一下：

c1, c2 列决定一行数据（但未创建联合唯一索引），两列各自有非唯一索引。
c1, c2 共同决定的行 不存在 并发更新场景。
执行 table_4269 伪代码间隔在 5s 左右。

这种场景下，依然会出现 write conflict 这类提示，比较令人疑惑。

按照文档中所说，可能不会影响具体业务，但产生这种冲突，总归是有缘由的，消除 conflict 本身也算是业务优化的一方面吧。

6

是否存在多个 tidb 节点并发 update 的情况，如果觉得业务场景不太可能出现 write conflict 报错，可以打开各个 tidb 节点的 general log 抓一下 conflict 前后的 sql 确认下