| Bug #69873 | Replication stop with "Error in Xid_log_event: Commit could not be completed" | ||
|---|---|---|---|
| Submitted: | 30 Jul 2013 16:17 | Modified: | 2 Sep 2014 14:57 |
| Reporter: | Alexander Du | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Row Based Replication ( RBR ) | Severity: | S2 (Serious) |
| Version: | 5.6.12, 5.6.13 | OS: | Linux (CentOS 5.7 x86_64) |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | replication, stop | ||
[8 Aug 2013 10:18]
Alexander Du
Upgrade master to 5.6.12 did not change anything. The error remains the same
[14 Aug 2013 7:12]
Boris Uchitel
This is what I see in error log in my case: 2013-08-13 22:04:08 27852 [ERROR] Slave SQL: Error in Xid_log_event: Commit could not be completed, '', Error_code: 0 2013-08-13 22:04:08 27852 [Warning] Slave: Unknown table 'gm.tmp_rank_res' Error_code: 1051 2013-08-13 22:04:08 27852 [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.000377' position 416194823 where `gm.tmp_rank_res` is a temporary table which is created on master in one of my stored procedures
[22 Aug 2013 12:09]
NOT_FOUND NOT_FOUND
We are seeing the same after upgrading from 5.6.10 to 5.6.12, running on FreeBSD 8.3. No mention of temporary tables in our logs: 2013-08-16 23:21:49 55009 [ERROR] Slave SQL: Error in Xid_log_event: Commit could not be completed, '', Error_code: 0 2013-08-16 23:21:49 55009 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'db02-bin.006200' position 2364009690 This happens at random intervals and requires a 'start slave' to recover. Until this issue is fixed, we need to run periodic 'start slave' commands through cron to avoid being woken up in the middle of the night..
[12 Sep 2013 19:50]
MySQL Verification Team
Hello!
Thank you for the report.
I'm able to reproduce this on slave box..
How to repeat:
if the slave thread is in "Waiting for commit lock" state and if you kill that thread then it can be observed..
slave1 [localhost] {msandbox} ((none)) > show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+
| 70 | msandbox | localhost | NULL | Query | 0 | init | show processlist |
| 71 | system user | | NULL | Connect | 425 | Waiting for master to send event | NULL |
| 72 | system user | | NULL | Connect | 109 | Waiting for commit lock | NULL |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+
slave1 [localhost] {msandbox} ((none)) > kill 72;
Query OK, 0 rows affected (0.00 sec)
slave1 [localhost] {msandbox} ((none)) > show processlist;
+----+-------------+-----------+------+---------+------+----------------------------------+-------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-------------+-----------+------+---------+------+----------------------------------+-------------------+
| 70 | msandbox | localhost | NULL | Query | 919 | init | show slave status |
| 71 | system user | | NULL | Connect | 1353 | Waiting for master to send event | NULL |
| 72 | system user | | NULL | Killed | 1037 | Reading event from the relay log | NULL |
| 73 | msandbox | localhost | NULL | Query | 911 | init | show slave status |
| 74 | msandbox | localhost | NULL | Query | 904 | init | show slave status |
| 75 | msandbox | localhost | NULL | Killed | 895 | init | show slave status |
| 78 | msandbox | localhost | NULL | Query | 0 | init | show processlist |
+----+-------------+-----------+------+---------+------+----------------------------------+-------------------+
7 rows in set (0.00 sec)
slave1 [localhost] {msandbox} ((none)) > show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 127.0.0.1
Master_User: rsandbox
Master_Port: 19278
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 27786
Relay_Log_File: mysql_sandbox19279-relay-bin.000009
Relay_Log_Pos: 2945
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error: Error in Xid_log_event: Commit could not be completed, ''
Skip_Counter: 0
Exec_Master_Log_Pos: 27786
Relay_Log_Space: 9949
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error: Error in Xid_log_event: Commit could not be completed, ''
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1
Master_UUID: eb76981c-1c58-11e3-bbb4-324defc71619
Master_Info_File: /data/ushastry/sandboxes/rsandbox_5_6_13/node1/data/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State:
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp: 130913 23:14:29
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 0
1 row in set (0.61 sec)
slave1 [localhost] {msandbox} ((none)) >
// from error log
2013-09-13 22:43:46 19001 [ERROR] Slave SQL: Error in Xid_log_event: Commit could not be completed, '', Error_code: 0
## Workaround
restart slave
[12 Sep 2013 19:52]
MySQL Verification Team
Exact steps are in http://bugs.mysql.com/70307
[3 Jul 2014 9:40]
MySQL Verification Team
With the latest build and steps from http://bugs.mysql.com/70307 , this time I see below error and text instead of ''. Restarting slave would fix the issue but endup losing the transaction which was executing at the time of killing the thread which was in "Waiting for commit lock" state. Would shortly add conf file used to the bug. mysql> show slave status\G *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 127.0.0.1 Master_User: repl Master_Port: 3306 Connect_Retry: 60 Master_Log_File: master-bin.000003 Read_Master_Log_Pos: 2163 Relay_Log_File: 70307S-relay-bin.000002 Relay_Log_Pos: 1634 Relay_Master_Log_File: master-bin.000003 Slave_IO_Running: Yes Slave_SQL_Running: No Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 1317 Last_Error: Error in Xid_log_event: Commit could not be completed, 'Query execution was interrupted' Skip_Counter: 0 Exec_Master_Log_Pos: 2163 Relay_Log_Space: 1808 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: NULL Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 1317 Last_SQL_Error: Error in Xid_log_event: Commit could not be completed, 'Query execution was interrupted' Replicate_Ignore_Server_Ids: Master_Server_Id: 1 Master_UUID: da0467b5-03d7-11e4-a140-00163e44510c Master_Info_File: /tmp/70307S/master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: 140705 05:39:38 Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: Executed_Gtid_Set: Auto_Position: 0 1 row in set (0.00 sec) mysql> select version(); +---------------------------------------+ | version() | +---------------------------------------+ | 5.6.20-enterprise-commercial-advanced | +---------------------------------------+ 1 row in set (0.00 sec)
[2 Sep 2014 14:57]
David Moss
The following was added to the 5.6.21 and 5.7.5 changelog with commit 4114: When an SQL thread which was waiting for a commit lock was killed and restarted it caused a transaction to be skipped on slave. This fix ensures that thread positions are correctly persisted and transactions resume at the correct position.
[2 Sep 2014 15:40]
David Moss
Posted by developer: The following was added to the 5.6.21 and 5.7.5 changelog with commit 4114: When an SQL thread which was waiting for a commit lock was killed and restarted it caused a transaction to be skipped on slave. This fix ensures that thread positions are correctly persisted and transactions resume at the correct position.
[25 Sep 2014 12:17]
Laurynas Biveinis
revno: 6118 committer: Sujatha Sivakumar <sujatha.sivakumar@oracle.com> branch nick: Bug17450876_mysql-5.6 timestamp: Tue 2014-08-19 09:57:08 +0530 message: Bug#17450876:REPLICATION STOP WITH "ERROR IN XID_LOG_EVENT: COMMIT COULD NOT BE COMPLETED" Problem: ======== When a SQL thread which is waiting for commit lock is killed and restarted it causes a transaction to be skipped on slave. Analysis: ======== when SQL thread is at a state where a DML is waiting for MDL commit lock if SQL thread is killed then position are getting updated in memory. i.e in the existing design positions are flushed before the actual commit because of this rli object will have its positions updated but the transaction is yet to be committed. When the SQL thread is restarted it reads position from the rli object and hence the last transaction gets skipped on slave. Fix: === When SQL thread is killed at a stage where it is waiting for commit lock, the commit fails and an error is reported back saying "Commit could not be completed and Query execution was interrupted". As part of fix SQL threads positions that existed before the commit are persisted and they are restored back on error. Similar symptoms exist in case of MTS as well. In MTS "The slave coordinator and worker threads are stopped, possibly leaving data in inconsistent state" error is reported. In MTS a bitmap is maintained for successful commits. This bit map is cleared on error and the old positions are retrieved from the checkpoint which points to old positions.
[30 Sep 2014 13:44]
David Moss
Posted by developer: Reopened by merge, no new changelog entries needed. Set back to Closed.
Description: I have had several stops of replication with following messages in error.log Server run as slave and as master for another slave in chain of replications. This happend after upgrade from 5.5.28 to 5.6.12 Master runing MySQL 5.5.28 2013-07-30 16:53:50 32726 [ERROR] Slave SQL: Error in Xid_log_event: Commit could not be completed, '', Error_code: 0 2013-07-30 16:53:50 32726 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'log-bin.012468' position 408143139 show slave status\G ... Connect_Retry: 60 Master_Log_File: log-bin.012471 Read_Master_Log_Pos: 72952613 Relay_Log_File: relay-bin.013534 Relay_Log_Pos: 408143296 Relay_Master_Log_File: log-bin.012468 Slave_IO_Running: Yes Slave_SQL_Running: No Replicate_Do_DB: Replicate_Ignore_DB: Replicate_Do_Table: Replicate_Ignore_Table: Replicate_Wild_Do_Table: Replicate_Wild_Ignore_Table: Last_Errno: 0 Last_Error: Error in Xid_log_event: Commit could not be completed, '' Skip_Counter: 0 Exec_Master_Log_Pos: 408143139 Relay_Log_Space: 3295080657 Until_Condition: None Until_Log_File: Until_Log_Pos: 0 Master_SSL_Allowed: No Master_SSL_CA_File: Master_SSL_CA_Path: Master_SSL_Cert: Master_SSL_Cipher: Master_SSL_Key: Seconds_Behind_Master: NULL Master_SSL_Verify_Server_Cert: No Last_IO_Errno: 0 Last_IO_Error: Last_SQL_Errno: 0 Last_SQL_Error: Error in Xid_log_event: Commit could not be completed, '' Replicate_Ignore_Server_Ids: Master_Server_Id: 3 Master_UUID: Master_Info_File: master.info SQL_Delay: 0 SQL_Remaining_Delay: NULL Slave_SQL_Running_State: Master_Retry_Count: 86400 Master_Bind: Last_IO_Error_Timestamp: Last_SQL_Error_Timestamp: 130730 16:53:50 Master_SSL_Crl: Master_SSL_Crlpath: Retrieved_Gtid_Set: Executed_Gtid_Set: Auto_Position: 0 How to repeat: Problem occurs randomly