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

🪐 TiDB 技术问题 部署&运维管理
9
前置条件

执行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]

image
image1844×760 78.4 KB

1 个赞