如何从TiDB日志，定位写冲突的语句

mao_siyu · 2020 年1 月 10 日 10:21

【TiDB 版本】：

3.0.5

【问题描述】：

当前这个日志表明的意思是什么?, 是指这两条SQL发的冲突？还是这两条语句，与其它的SQL发生了冲突？

如下监控指标，回滚的事务与冲突的数量，感觉对不上号，看不透了！也帮忙解读一下好吗？

yilong · 2020 年1 月 10 日 11:21

请参考下这个帖子https://asktug.com/t/pessimistic-write-conflict-retry-statement/563/8，多谢

mao_siyu · 2020 年1 月 10 日 11:26

老师，他和我的情况不一样啊

我想了解这个日志怎么解读
我开启的是乐观锁，的事务重试功能

麻烦老师有空的时候能给说一下吗？

yilong · 2020 年1 月 10 日 13:31

1.先排查是否是集群太忙，导致tikv太慢 2. 写写冲突的时候会出现。举个例子 txnStartTS：本事务的 StartTS conflictStartTS：冲突事务的 StartTS conflictCommitTS：冲突事务的 CommitTS key={tableID=14999, indexID=2, indexValues={1000001606, 10,}} ：本事务中，冲突的数据，indexID 表示冲突的是索引数据，indexValues表示索引的列值，最后的 10 是索引对应的 handle primary={tableID=14999, indexID=4, indexValues={1879832947,10, }}：本事务的 primary key

mao_siyu · 2020 年1 月 11 日 02:13

txnStartTS：本事务的

StartTS conflictStartTS：冲突事务的

StartTS conflictCommitTS：冲突事务的

CommitTS key={tableID=14999, indexID=2, indexValues={1000001606, 10,}} ：本事务中，冲突的数据，indexID 表示冲突的是索引数据，indexValues表示索引的列值，最后的 10 是索引对应的 handle primary={tableID=14999, indexID=4, indexValues={1879832947,10, }}：本事务的 primary key

老师，这个最终两个事务都回滚重试了对吧！正常mysql回滚其中一个事务，是因为他是悲观锁，乐观锁是都回滚吗？

yilong · 2020 年1 月 11 日 03:34

如果排除掉写入非常慢的原因。这里的txnstartts代表的是这个事务回滚了，对应事务为conflictStartTS的事务，应该已经提交成功了. 你可以自己模拟唯一索引，使用显示事务，同时提交一行，看一下报错信息

mao_siyu · 2020 年1 月 12 日 01:35

乐观锁事务，日志分析

[2020/01/10 18:36:55.259 +08:00] [WARN] [session.go:419] [sql] [conn=314] [label=general] [error="[kv:9007]Write conflict, txnStartTS=413834427449737221, conflictStartTS=413834427449737218, conflictCommitTS=413834427462844422, key={tableID=12532, handle=627493} primary={tableID=12532, handle=627493} [try again later] [txn="Txn{state=invalid}"]

拆解日志

[2020/01/10 18:36:55.259 +08:00]               // 异常发生时间
[WARN][session.go:419] [sql] [conn=314] [label=general]
[error="                                       // 异常信息
    [kv:9007]Write conflict,                   // 写冲突
    txnStartTS=413834427449737221,             //
    conflictStartTS=413834427449737218,        //
    conflictCommitTS=413834427462844422,       //
    key={tableID=12532, handle=627493}         //
    primary={tableID=12532, handle=627493}     //
    [try again later]                          // 稍后会重试
    [txn="Txn{state=invalid}                   //
"]

请老师帮忙补充上面的信息注释，因为没有 index 与 indexValue，我怕理解错老师上面说的含义,
我看官方文档中 8005 与 9007 都是写冲突，解决方案也一样，那么这两个错误码的区别是什么？

8005: 读写冲突？
9007: 写写冲突？

上面的异常，与异常码，会随着事务是悲观锁还是乐观锁，有不同之处吗？

yilong · 2020 年1 月 12 日 07:09

请先测试一下，之后我们再一起探讨，多谢

mao_siyu · 2020 年1 月 13 日 02:01

前置条件

执行SQL的客户端地址: 172.160.180.32

执行SQL的客户端地址: 172.160.180.46

TiDB-Server: 172.160.180.33

开启了乐观锁事务重试

创建数据库

CREATE TABLE `table1` (
  `id` bigint(20) NOT NULL,
  `name` varchar(255) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

测试插入数据冲突

事务一	Step	事务二
172.160.180.32	客户端	172.160.180.46
BEGIN; Query OK, 0 rows affected (0.01 sec)	1	BEGIN; Query OK, 0 rows affected (0.01 sec)
`INSERT INTO table1(id,name) VALUES (1000, '张三');` Query OK, 1 row affected (0.00 sec)	2	`INSERT INTO table1(id,name) VALUES (1000, 'PingCAP');` Query OK, 1 row affected (0.00 sec)
	3	COMMIT; Query `OK`, 0 rows affected (0.02 sec)
COMMIT; `ERROR 1062 (23000): Duplicate entry '1000' for key 'PRIMARY'`	4

查看最终结果

MySQL [eric]> SELECT * FROM table1;
+------+---------+
| id   | name    |
+------+---------+
| 1000 | PingCAP |
+------+---------+
1 row in set (0.01 sec)

MySQL [eric]>

查看TiDB.log 冲突日志

[2020/01/13 09:04:12.352 +08:00] [INFO] [set.go:192] ["set session var"] [conn=32186] [name=transaction_read_only] [val=0]
[2020/01/13 09:04:14.914 +08:00] [WARN] [session.go:419] [sql] [conn=32148] [label=general] [error="[kv:9007]Write conflict, txnStartTS=413893216290471948, conflictStartTS=413893242190299137, conflictCommitTS=413893250919694337, key={tableID=15314, handle=1000} primary={tableID=15314, handle=1000} [try again later]"] [txn="Txn{state=invalid}"]
[2020/01/13 09:04:14.914 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0] [queryNum=0] [sql=BEGIN]
[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0] [queryNum=1] [sql="INSERT INTO table1(id,name) VALUES (1000, '张三')"]
[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0] [queryNum=2] [sql=COMMIT]
[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:632] ["transaction association"] [conn=32148] ["retrying txnStartTS"=413893251535732737] ["original txnStartTS"=413893216290471948]
[2020/01/13 09:04:14.919 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=32148] [txnStartTS=413893216290471948]
[2020/01/13 09:04:14.919 +08:00] [WARN] [session.go:646] [sql] [conn=32148] [label=general] [session="{\
  \"currDBName\": \"eric\",\
  \"id\": 32148,\
  \"status\": 2,\
  \"strictMode\": true,\
  \"user\": {\
    \"Username\": \"root\",\
    \"Hostname\": \"172.160.180.32\",\
    \"CurrentUser\": false,\
    \"AuthUsername\": \"root\",\
    \"AuthHostname\": \"%\"\
  }\
}"] [error="[kv:1062]Duplicate entry '1000' for key 'PRIMARY'"]

拆解日志

[2020/01/13 09:04:14.914 +08:00] [WARN] [session.go:419] [sql] [conn=32148] [label=general]
[error="[kv:9007]                           // 写冲突
Write conflict,
 txnStartTS=413893216290471948,             // 原事务(事务A)
 conflictStartTS=413893242190299137,        // 与原事务相冲突的事务(事务B)
 conflictCommitTS=413893250919694337,       // 相冲突的事务已经提交(事务B已经提交)
 key={tableID=15314, handle=1000}
 primary={tableID=15314, handle=1000}
 [try again later]"]
 [txn="Txn{state=invalid}"]

// 最后提交的事务
[2020/01/13 09:04:14.914 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0]
 [queryNum=0] [sql=BEGIN]
[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0]
 [queryNum=1] [sql="INSERT INTO table1(id,name) VALUES (1000, '张三')"]
[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:611] [retrying] [conn=32148] [schemaVersion=13707] [retryCnt=0]
 [queryNum=2] [sql=COMMIT]


[2020/01/13 09:04:14.915 +08:00] [WARN] [session.go:632]
 ["transaction association"] [conn=32148]    //
 ["retrying txnStartTS"=413893251535732737]  // 原事务(事务A) 被重试
 ["original txnStartTS"=413893216290471948]  // 原事务(事务A)

// 被回滚的事务(被清理的事务)
[2020/01/13 09:04:14.919 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=32148] [txnStartTS=413893216290471948]

// 被回滚的事务，是由哪个客户端发起
[2020/01/13 09:04:14.919 +08:00] [WARN] [session.go:646] [sql] [conn=32148] [label=general]
 [session="{
    "currDBName": "eric",
    "id": 32148,
    "status": 2,
    "strictMode": true,
    "user": {
      "Username": "root",
      "Hostname": "172.160.180.32",
      "CurrentUser": false,
      "AuthUsername": "root",
      "AuthHostname": "%"
    }
 }"]
 // 事务冲突原因
 [error="[kv:1062]Duplicate entry '1000' for key 'PRIMARY'"]

测试更新数据冲突

事务一	Step	事务二
172.160.180.32	客户端	172.160.180.46
BEGIN; Query OK, 0 rows affected (0.01 sec)	1	BEGIN; Query OK, 0 rows affected (0.00 sec)
`UPDATE table1 SET name='TiDB' WHERE id=1000;` Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0	2	`UPDATE table1 SET name='TUG' WHERE id=1000;` Query OK, 1 row affected (0.00 sec) Rows matched: 1 Changed: 1 Warnings: 0
COMMIT; Query OK, 0 rows affected (0.01 sec)	3
	4	COMMIT; Query OK, 0 rows affected (0.01 sec)

查看最终结果

MySQL [eric]> SELECT * FROM table1;
+------+------+
| id   | name |
+------+------+
| 1000 | TUG  |
+------+------+
1 row in set (0.01 sec)

MySQL [eric]>

冲突日志

[2020/01/13 10:08:32.340 +08:00] [INFO] [set.go:192] ["set session var"] [conn=32560] [name=sql_select_limit] [val=1]
[2020/01/13 10:08:36.988 +08:00] [WARN] [session.go:419] [sql] [conn=32152] [label=general] [error="[kv:9007]Write conflict, txnStartTS=413894257093902337, conflictStartTS=413894221350567937, conflictCommitTS=413894262690676738, key={tableID=15314, handle=1000} primary={tableID=15314, handle=1000} [try again later]"] [txn="Txn{state=invalid}"]
[2020/01/13 10:08:36.988 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0] [queryNum=0] [sql=BEGIN]
[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0] [queryNum=1] [sql="UPDATE table1 SET name='TUG' WHERE id=1000"]
[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0] [queryNum=2] [sql=COMMIT]
[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:632] ["transaction association"] [conn=32152] ["retrying txnStartTS"=413894263948967942] ["original txnStartTS"=413894257093902337]
[2020/01/13 10:08:36.991 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=32152] [txnStartTS=413894257093902337]
[2020/01/13 10:08:37.663 +08:00] [INFO] [set.go:192] ["set session var"] [conn=24502] [name=tx_read_only] [val=1]

拆解日志

[2020/01/13 10:08:36.988 +08:00] [WARN] [session.go:419] [sql] [conn=32152] [label=general]
[error="[kv:9007]
 Write conflict,
 txnStartTS=413894257093902337,
 conflictStartTS=413894221350567937,
 conflictCommitTS=413894262690676738,
 key={tableID=15314, handle=1000}
 primary={tableID=15314, handle=1000}
 [try again later]"] [txn="Txn{state=invalid}"]

// 最后提交的事务
[2020/01/13 10:08:36.988 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0]
 [queryNum=0] [sql=BEGIN]
[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0]
 [queryNum=1] [sql="UPDATE table1 SET name='TUG' WHERE id=1000"]
[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:611] [retrying] [conn=32152] [schemaVersion=13712] [retryCnt=0]
 [queryNum=2] [sql=COMMIT]


[2020/01/13 10:08:36.989 +08:00] [WARN] [session.go:632]
 ["transaction association"] [conn=32152]
 ["retrying txnStartTS"=413894263948967942]
 ["original txnStartTS"=413894257093902337]

// 被回滚的事务(被清理的事务)
[2020/01/13 10:08:36.991 +08:00] [INFO] [2pc.go:1039] ["2PC clean up done"] [conn=32152] [txnStartTS=413894257093902337]

GangShen · 2020 年1 月 15 日 12:29

感谢分享

h5n1 · 2021 年6 月 25 日 03:11

请问如何找到conflict事务的信息？

Lucien-卢西恩 · 2021 年6 月 26 日 02:06

https://docs.pingcap.com/zh/tidb/stable/troubleshoot-write-conflicts#如何解决写写冲突问题

system · 2022 年10 月 31 日 19:11

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。

如何从TiDB日志，定位写冲突的语句

【TiDB 版本】：

【问题描述】：

当前这个日志表明的意思是什么?, 是指这两条SQL发的冲突？ 还是这两条语句，与其它的SQL发生了冲突？

如下监控指标，回滚的事务与冲突的数量，感觉对不上号，看不透了！也帮忙解读一下好吗？

老师，这个最终两个事务都回滚重试了对吧！正常mysql回滚其中一个事务，是因为他是悲观锁， 乐观锁是都回滚吗？

乐观锁事务，日志分析

前置条件

创建数据库

测试插入数据冲突

查看最终结果

查看TiDB.log 冲突日志

拆解日志

测试更新数据冲突

查看最终结果

冲突日志

拆解日志

当前这个日志表明的意思是什么?, 是指这两条SQL发的冲突？还是这两条语句，与其它的SQL发生了冲突？

老师，这个最终两个事务都回滚重试了对吧！正常mysql回滚其中一个事务，是因为他是悲观锁，乐观锁是都回滚吗？