MySQL唯 一鍵約束場景下卻能插入重複行？

龍山游龍發表於2023-03-10
MySql

1 、故障描述

某次，使用者的一套 MySQL從庫在同步時出現寫入衝突報錯。透過檢查從庫的錯誤日誌資訊，可以很清晰的發現報錯共有兩處，先是寫入衝突報錯，使用者選擇跳過該衝突事務之後，又碰到了刪除報錯。透過檢視從庫的binlog日誌可以發現從庫並不存在寫入的重複行資料，那從庫的第一個報錯又從何而來呢。

2022-07-07 05:39:22 154606 [ERROR] Slave SQL: Could not execute Write_rows event on table zntj_gg.t_ius_user_sub_service; Duplicate entry '03254A7657C525984A2BB-aaa_001_86_3_5_1_1_gcw2-fitness' for key 'std_id', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.004166, end_log_pos 255398155, Error_code: 1062
2022-07-07 05:39:22 154606 [Warning] Slave: Duplicate entry '03254A7657C525984A2BB-aaa_001_86_3_5_1_1_gcw2-fitness' for key 'std_id' Error_code: 1062
2022-07-07 05:39:22 154606 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.004166' position 255397852
2022-07-07 09:27:32 154606 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2022-07-07 09:27:32 154606 [Note] Slave I/O thread killed while reading event
2022-07-07 09:27:32 154606 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.004167', position 58828583
2022-07-07 09:29:30 154606 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2022-07-07 09:29:30 154606 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2022-07-07 09:29:30 154606 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.004166' at position 255397852, relay log './mysqld-relay-bin.006839' position: 255398015
2022-07-07 09:29:30 154606 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398015', master_log_name='mysql-bin.004166', master_log_pos='255397852' and new position at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398349', master_log_name='mysql-bin.004166', master_log_pos='255398186' 
2022-07-07 09:29:30 154606 [Note] Slave I/O thread: connected to master 'replicauser@125.210.102.17:3306',replication started in log 'mysql-bin.004167' at position 58828583
2022-07-07 09:29:30 154606 [ERROR] Slave SQL: Could not execute Delete_rows event on table zntj_gg.t_ius_user_sub_service; Can't find record in 't_ius_user_sub_service', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.004166, end_log_pos 255398594, Error_code: 1032
2022-07-07 09:29:30 154606 [Warning] Slave: Can't find record in 't_ius_user_sub_service' Error_code: 1032
2022-07-07 09:29:30 154606 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.004166' position 255398186
2022-07-07 09:36:27 154606 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2022-07-07 09:36:27 154606 [Note] Slave I/O thread killed while reading event
2022-07-07 09:36:27 154606 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.004167', position 84764060
2022-07-07 09:37:05 154606 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2022-07-07 09:37:05 154606 [Note] Slave I/O thread: connected to master 'replicauser@125.210.102.17:3306',replication started in log 'mysql-bin.004167' at position 84764060
2022-07-07 09:37:05 154606 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2022-07-07 09:37:05 154606 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.004166' at position 255398186, relay log './mysqld-relay-bin.006839' position: 255398349
2022-07-07 09:37:05 154606 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398349', master_log_name='mysql-bin.004166', master_log_pos='255398186' and new position at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398788', master_log_name='mysql-bin.004166', master_log_pos='255398625'

 

2 、根因分析

透過報錯資訊，檢查相關表建表語句，懷疑當時從庫是因為唯 一鍵衝突進而產生報錯，然後使用者選擇使用 SQL_SLAVE_SKIP_COUNTER跳過該事務，使該資料未能寫入，導致後面的delete事務無法找到匹配的行。

| t_ius_user_sub_service | CREATE TABLE `t_ius_user_sub_service` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `createTime` datetime DEFAULT NULL,
  `lastUpdateTime` datetime DEFAULT NULL,
  `status` bigint(20) DEFAULT NULL,
  `cust_code` varchar(255) DEFAULT NULL,
  `std_id` varchar(255) DEFAULT NULL,
  `sub_service_code` varchar(255) DEFAULT NULL,
  `serviceType` varchar(255) DEFAULT NULL,
  `watchnum` int(11) NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `std_id` (`std_id`,`sub_service_code`,`serviceType`) USING BTREE,
  KEY `sub_service_code` (`sub_service_code`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=2913132 DEFAULT CHARSET=utf8


很快，透過解析主庫的 binlog日誌，得到了確實的證據，在主庫的binlog日誌中，可以看到先是插入了兩條語句，然後透過delete刪除了這兩條語句。那麼問題來了，這兩條插入的語句，根據建表語句中的設定，應該是會產生唯 一鍵衝突的，為什麼從庫執行失敗報錯了，主庫卻能順利執行呢？

# at 255397487
#220707  5:39:22 server id 10261  end_log_pos 255397518 CRC32 0xea016589  Xid = 270516762358
COMMIT/*!*/;
# at 255397518
#220707  5:39:22 server id 10261  end_log_pos 255397593 CRC32 0x6f5eeff0  Query thread_id=172971976 exec_time=0    error_code=0
SET TIMESTAMP=1657143562/*!*/;
BEGIN
/*!*/;
# at 255397593
#220707  5:39:22 server id 10261  end_log_pos 255397680 CRC32 0x40ae4e57  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255397680
#220707  5:39:22 server id 10261  end_log_pos 255397821 CRC32 0x8658dd38  Write_rows: table id 270345775 flags: STMT_END_F
### INSERT INTO `zntj_gg`.`t_ius_user_sub_service`
### SET
###   @1=2912517
###   @2='2022-07-07 05:39:18'
###   @3='2022-07-07 05:39:18'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255397821
#220707  5:39:22 server id 10261  end_log_pos 255397852 CRC32 0x78e79f44  Xid = 270516762129
COMMIT/*!*/;
# at 255397852
#220707  5:39:22 server id 10261  end_log_pos 255397927 CRC32 0x7833f5aa  Query thread_id=172587714 exec_time=0    error_code=0
SET TIMESTAMP=1657143562/*!*/;
BEGIN
/*!*/;
# at 255397927
#220707  5:39:22 server id 10261  end_log_pos 255398014 CRC32 0xba4235b0  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255398014
#220707  5:39:22 server id 10261  end_log_pos 255398155 CRC32 0xe772beb9  Write_rows: table id 270345775 flags: STMT_END_F
### INSERT INTO `zntj_gg`.`t_ius_user_sub_service`
### SET
###   @1=2912518
###   @2='2022-07-07 05:38:38'
###   @3='2022-07-07 05:38:38'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255398155
#220707  5:39:22 server id 10261  end_log_pos 255398186 CRC32 0x1e02a19d  Xid = 270516762223
COMMIT/*!*/;
# at 255398186
#220707  5:36:36 server id 10261  end_log_pos 255398261 CRC32 0x0080cbe2  Query thread_id=149724384 exec_time=166  error_code=0
SET TIMESTAMP=1657143396/*!*/;
BEGIN
/*!*/;
# at 255398261
#220707  5:36:36 server id 10261  end_log_pos 255398348 CRC32 0xb2c4244c  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255398348
#220707  5:36:36 server id 10261  end_log_pos 255398594 CRC32 0xc964c586  Delete_rows: table id 270345775 flags: STMT_END_F
### DELETE FROM `zntj_gg`.`t_ius_user_sub_service`
### WHERE
###   @1=2912517
###   @2='2022-07-07 05:39:18'
###   @3='2022-07-07 05:39:18'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
### DELETE FROM `zntj_gg`.`t_ius_user_sub_service`
### WHERE
###   @1=2912518
###   @2='2022-07-07 05:38:38'
###   @3='2022-07-07 05:38:38'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255398594
#220707  5:39:22 server id 10261  end_log_pos 255398625 CRC32 0xd01c4287  Xid = 270512016580
COMMIT/*!*/;


排查到這一步，不覺的陷入了沉思，在唯 一鍵約束存在的前提下，居然能插入重複行？？？難道，該約束被禁用了？首先，嘗試在常規情況下主庫能插入兩條唯 一鍵衝突資料的辦法。方式 1：透過設定unique_checks引數為0來關閉資料庫的唯 一鍵檢查。方式2：可以修改插入語句，透過insert ignore、replace into、insert on duplicate key update三種手段來規避唯 一鍵衝突。然而，實際情況unique_checks引數為1，且業務執行語句時並未修改unique_checks引數。而透過binlog日誌的記錄可以發現，當時確實是有兩個資料插入成功，與insert ignore、replace into、insert on duplicate key update這些手段的規避結果不同。

分析到這裡還沒有確切的證據，我們便需要模擬環境，嘗試對報錯的場景進行復現，透過分析主庫的 binlog日誌，我們可以發現，delete事務是在5:36:36開始執行，然後和兩個insert事務一起在5:39:22結束。模擬實際環境資料庫的版本和配置檔案，建立一個和原庫配置相同的資料庫來進行場景復現。

 

然後開啟四個視窗，第一個視窗加持鎖，然後第二個視窗對錶進行 delete操作，然後第三個視窗和第四個視窗準備好insert語句，最後根據binlog記錄依次執行。先執行insert語句，然後解鎖執行delete語句，儘量保持在較短時間內執行，以模擬場景中的同時進行。

 

 

最後透過幾輪測試會發現，模擬的結果與實際報錯場景不同，在測試中，插入唯 一鍵衝突的資料會報錯。說明實際場景中出現的情況是不合邏輯的，不常見的。

此時，相信很多朋友會納悶，那是不是碰到 MySQL  BUG 了。懷揣著同樣的想法，筆者去 MySQL  BUG 網站撈了一把，幸運的發現了新的收穫，確實存在類似的 B UG ，如下：

 

詳情可以參考：

3 、解決方案

為了防止業務表上出現不必要的重複行，或者避免資料錯亂，建議將當前 MySQL升級至當前系列的最新小版本或直接升級到高版本。

 


來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/30310891/viewspace-2939153/，如需轉載，請註明出處，否則將追究法律責任。

相關文章