1. 程式人生 > >MySQL復制錯誤1837的相關缺陷一例

MySQL復制錯誤1837的相關缺陷一例

contents div pty exec col res 測試結果 last nsis

故障現象

主從gtid報錯,復制錯誤1837,這個復制故障可以說是第一次遇到。

Last_Errno: 1837  
Last_Error: Error ‘When @@SESSION.GTID_NEXT is set to a GTID, you must explicitly set it to a different value after a COMMIT or ROLLBACK. Please check GTID_NEXT variable manual page for detailed explanation. Current @@SESSION.GTID_NEXT is ‘2a46b388-5469-11e6-b949-845b123e2eff:64734471‘.‘ on query. Default database: ‘fander‘. Query: ‘delete from t_fander

故障可能原因

從故障的報錯,網上搜到的答案引導了我去看官方文檔的“gtid的限制”的這一章節。
參考:https://dev.mysql.com/doc/refman/5.6/en/replication-gtids-restrictions.html

  1. 涉及非事務性存儲引擎的更新。例如,myisam引擎表,主庫執行insert delayed into xx values...
  2. enforce_gtid_consistency為OFF,CREATE TABLE ... SELECT語句。
  3. 主從引擎不一致,主庫innodb引擎一個事務中寫入兩條數據,傳到從庫的myisam引擎執行這個事務
  4. 臨時表
  5. 較早之前的一些bug

故障可能原因的分析

1.檢查過所有表都是innodb表,沒有myisam表,故排除。

mysql> select table_schema,table_name,engine from information_schema.tables where engine !=‘innodb‘ and table_schema not in (‘mysql‘,‘information_schema‘,‘performance_schema‘);
Empty set (0.00 sec)

2.事實上檢查過enforce_gtid_consistency主從庫都為on,CREATE TABLE ... SELECT語句不能執行成功,並且這次故障並不涉及CREATE TABLE ... SELECT語句,故排除。

mysql> create table t7 select * from t6;
ERROR 1786 (HY000): CREATE TABLE ... SELECT is forbidden when @@GLOBAL.ENFORCE_GTID_CONSISTENCY = 1.

3.由於這個case是第一次發生了,上周才重做過從庫,所以不存在主從不一致引擎的可能,並且第1步分析也知道庫裏並沒有myisam表,故排除。

4.沒有涉及臨時表
5.查閱了這些bug在5.6.9和5.6.7上分別修復了。我們目前MySQL版本為5.6.23

然而並沒有找到合適的答案,接著申請權限,來解析一下binlog探個究竟吧。

故障定位

從1837報錯的英文信息描述上,我們得出以下信息:

  1. 發生故障的gtid號是2a46b388-5469-11e6-b949-845b123e2eff:64734471
  2. 發生故障的sql為delete from t_fander,或前後。
  3. 提示信息:設置為GTID時,您必須在提交或回滾之後顯式地將其設置為不同的值

出於隱私考慮,我沒有辦法展示原始的binlog。
在解析了主從兩個數據庫的binlog後,發現從庫大概是在執行以下sql時出了問題:
主庫:

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a=‘123‘;
use fander;delete from t5;
use fander;delete from t6;
commit;

#原update的sql比這個復雜得多,有where條件的,請不要糾結我這個sql為什麽沒事關聯那麽多張表。。。

主庫上著3條DML操作是同一個事務,但在從庫回放時,發生了事務的拆分。變成如下的樣子。
從庫:

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a=‘123‘;
commit; #從庫解析時,無端端給加了一個commit。
use fander;delete from t5; #這條在從庫binlog裏並沒有。也就是上面commit後,正常需要設置不同的@@SESSION.GTID_NEXT,但他沒有設置,所以報復制錯誤了。事務發生了異常拆分了!!

故障重現

主庫上操作:

vi /tmp/c.sql
begin;
#經過多次測試,update語句可以修改為這個更簡單的語句
use fander;update t1,t2,t3,t4 set t1.a=‘123‘;
use fander;delete from t5;
use fander;delete from t6;
commit;
mysql> create database fander;
mysql> set global  tx_isolation=‘Repeatable-Read‘;
mysql> set global  binlog_format=‘Mixed‘;
mysql> create table t1(a int);
mysql> create table t2(a int);
mysql> create table t3(a int);
mysql> create table t4(a int);
mysql> create table t5(a int);
mysql> create table t6(a int);
mysql> flush logs;
mysql> exit
mysql> source /tmp/c.sql

binlog 如下:

SET @@SESSION.GTID_NEXT= ‘316d072f-9633-11e8-b0f3-000c294a5f55:16719‘/*!*/;
# at 1588
#180815 21:51:29 server id 897905305  end_log_pos 1672 CRC32 0xbf36600e         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1672
#180815 21:51:29 server id 897905305  end_log_pos 1784 CRC32 0xdc2d6070         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
update t1,t2,t3,t4 set t1.a=‘123‘
/*!*/;
# at 1784
#180815 21:51:29 server id 897905305  end_log_pos 1869 CRC32 0x931ab661         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
COMMIT   <<<-----被額外添加的commit----------
/*!*/;
# at 1869
#180815 21:51:29 server id 897905305  end_log_pos 1917 CRC32 0x116a4cfb         GTID [commit=yes]
SET @@SESSION.GTID_NEXT= ‘316d072f-9633-11e8-b0f3-000c294a5f55:16720‘/*!*/;
# at 1917
#180815 21:51:29 server id 897905305  end_log_pos 1992 CRC32 0x6fe6ccaa         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1992
#180815 21:51:29 server id 897905305  end_log_pos 2076 CRC32 0x0695b437         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t5
/*!*/;
# at 2076
#180815 21:51:29 server id 897905305  end_log_pos 2160 CRC32 0x56083744         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t6
/*!*/;
# at 2160
#180815 21:51:29 server id 897905305  end_log_pos 2191 CRC32 0xfe7fe294         Xid = 31066
COMMIT/*!*/;

測試結果:

數據庫版本: MySQL5.6.23
參數:
tx_isolation=‘Repeatable-Read‘;
binlog_format=‘Mixed‘;
autocommit=1;
結果:
多表關聯update操作後,事務就被拆分了。

事務被拆分,這現象不正常啊?下面測試是否BUG。在參數配置不變的情況下,升級實例為mysql5.7.21,我們再來一次測試。

測試步驟一樣。binlog如下:

BEGIN
/*!*/;
# at 303
#180816 15:01:12 server id 352148329  end_log_pos 415 CRC32 0xe61e4415  Query thread_id=1477446 exec_time=0 e
rror_code=0
use `fander`/*!*/;
SET TIMESTAMP=1534402872/*!*/;
update t1,t2,t3,t4 set t1.a=‘123‘
/*!*/;
# at 415
#180816 15:01:12 server id 352148329  end_log_pos 499 CRC32 0xd51c509c  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t5
/*!*/;
# at 499
#180816 15:01:12 server id 352148329  end_log_pos 583 CRC32 0x17e3871d  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t6
/*!*/;
# at 583
#180816 15:01:12 server id 352148329  end_log_pos 614 CRC32 0x59f429aa  Xid = 44831936
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= ‘AUTOMATIC‘ /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

測試結果:

數據庫版本: MySQL5.7.21
參數:
tx_isolation=‘Repeatable-Read‘;
binlog_format=‘Mixed‘;
autocommit=1;
結果:
可以看出update和delete之間並沒有自動添加commit,沒有自動拆分事務。

BUG確認

在查閱mysql bug庫後,發現這個是一個已知bug,並已經在5.6.27上修復了。

Replication: If statement based logging was in use, when updating multiple tables in a single statement, a single transaction could be logged as two different transactions. This was due to the binary logging process not properly identifying statements which were operating over transactional tables. The fix ensures that they are correctly identified, even if such statements do not change the contents of the tables. (Bug #16621582, Bug #21349028)

復制:如果使用基於語句的日誌記錄,當在單個語句中更新多個表時,會將單個事務記錄為兩個不同的事務。這是由於二進制日誌記錄過程無法正確識別在事務表上操作的語句。現在修復了,現在確保它們會被正確識別,即使語句不會修改表的內容。(bug 16621582,bug 21349028)

解決方法

解決方法就是避免不正確的拆事務的發生。

方案一:

開發修改sql。這個方案可以說是第一個排除的。因為只能解決這次問題,並不能根治。

方案二:

升級MySQL5.6.23到MySQL5.6.X(最新版本)或MySQL5.7.21。升級5.7.21是可行的,目前我們有提供MySQL5.7.21的安裝服務,但這需要測試sql兼容問題。

方案三:

修改binlog格式。從bug的描述可知,此問題只出現在基於語句的日誌記錄,所以binlog_format修改為row格式可以解決這個問題。

方案四:

修改事務隔離級別。因為RC事務隔離級別下是不支持statement格式的。所以
修改tx_isolation=‘Read-committed‘,在binlog_format=‘Mixed‘格式下,所有DML操作都會轉為row格式。這個方案解決的原理只是把binlog轉化為row格式,而改事務隔離級別是有風險的,尤其是涉及金錢交易,這個需要先與開發一同測試後方能修改。

經過選擇和測試,方案三解決了這次的問題。

原文: https://www.cnblogs.com/fander/p/9488935.html

MySQL復制錯誤1837的相關缺陷一例