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

【TiDB 版本】:

3.0.5

【问题描述】:

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

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

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

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

  1. 我想了解这个日志怎么解读

  2. 我开启的是乐观锁,的事务重试功能

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

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

1赞

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回滚其中一个事务,是因为他是悲观锁, 乐观锁是都回滚吗?

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

乐观锁事务,日志分析

[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}                   //
"]
  1. 请老师帮忙补充上面的信息注释,因为没有 index 与 indexValue,我怕理解错老师上面说的含义,

  2. 我看官方文档中 8005 与 9007 都是写冲突,解决方案也一样,那么这两个错误码的区别是什么?

  • 8005: 读写冲突?
  • 9007: 写写冲突?
  1. 上面的异常,与异常码, 会随着事务是 悲观锁 还是乐观锁,有不同之处吗?

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

前置条件

执行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="{\n  \"currDBName\": \"eric\",\n  \"id\": 32148,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": {\n    \"Username\": \"root\",\n    \"Hostname\": \"172.160.180.32\",\n    \"CurrentUser\": false,\n    \"AuthUsername\": \"root\",\n    \"AuthHostname\": \"%\"\n  }\n}"] [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]

感谢分享