[MDEV-22530] Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server. Created: 2020-05-12  Updated: 2023-05-12  Resolved: 2021-05-17

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.3.16, 10.4.12, 10.2
Fix Version/s: 10.2.39, 10.3.30, 10.4.20, 10.5.11

Type: Bug Priority: Critical
Reporter: suresh ramagiri Assignee: Sujatha Sivakumar (Inactive)
Resolution: Fixed Votes: 0
Labels: None
Environment:

CentOS/RHEL 7



 Description   

Aborting OPTIMIZE TABLE still logs in binary logs and replicates to the Slave server.

It is observed that while OPTIMIZE TABLE query is executing, aborting it will still have the entry of the same in the binary logs and it's getting replicated at the slave end. Tested and found this behavior at MariaDB server 10.3.16 and 10.4.12.

It doesn't look like an expected behavior and so reporting it.

Here is my test result.

Master:
=======

MariaDB [test]> show master status; ## Note the binary log position
+---------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+---------------+----------+--------------+------------------+
| binlog.000002 | 471 | | |
+---------------+----------+--------------+------------------+
1 row in set (0.000 sec)
 
MariaDB [test]> optimize table foo; ## OPTIMIZE query was aborted
^CCtrl-C -- query killed. Continuing normally.
+----------+----------+----------+-------------------------------------------------------------------+
| Table | Op | Msg_type | Msg_text |
+----------+----------+----------+-------------------------------------------------------------------+
+----------+----------+----------+-------------------------------------------------------------------+
3 rows in set, 1 warning (1.976 sec)
 
MariaDB [test]> show master status; ## Binary log position changed
+---------------+----------+--------------+------------------+
| File | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+---------------+----------+--------------+------------------+
| binlog.000002 | 598 | | |
+---------------+----------+--------------+------------------+
1 row in set (0.000 sec)
 
MariaDB [test]> show binlog events in 'binlog.000002'; ## Binary log events, clearly showing OPTIMIZE query.
+---------------+-----+-------------------+-----------+-------------+------------------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+---------------+-----+-------------------+-----------+-------------+------------------------------------------------+
| binlog.000002 | 4 | Format_desc | 2 | 256 | Server ver: 10.4.12-MariaDB-log, Binlog ver: 4 |
| binlog.000002 | 256 | Gtid_list | 2 | 299 | [0-1-44031] |
| binlog.000002 | 299 | Binlog_checkpoint | 2 | 339 | binlog.000002 |
| binlog.000002 | 339 | Gtid | 2 | 381 | GTID 0-2-44032 |
| binlog.000002 | 381 | Query | 2 | 471 | use `test`; create table pp (a int) |
| binlog.000002 | 471 | Gtid | 2 | 513 | GTID 0-2-44033 |
| binlog.000002 | 513 | Query | 2 | 598 | use `test`; optimize table foo |
+---------------+-----+-------------------+-----------+-------------+------------------------------------------------+
7 rows in set (0.000 sec)
 
MariaDB [test]> select @@version;
+---------------------+
| @@version |
+---------------------+
| 10.4.12-MariaDB-log |
+---------------------+
1 row in set (0.000 sec)

Slave:
======

You can see in the processlist, OPTIMIZE TABLE query is being executed. "show slave status" showed it moved to the changed master binary log position.

MariaDB [(none)]> show processlist;
+----+-------------+---------------------------------+------+-------------+------+-----------------------------------------------------------------------+--------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+----+-------------+---------------------------------+------+-------------+------+-----------------------------------------------------------------------+--------------------+----------+
| 4 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 1 | system user | | NULL | Daemon | NULL | InnoDB purge coordinator | NULL | 0.000 |
| 2 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 3 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 5 | system user | | NULL | Daemon | NULL | InnoDB shutdown handler | NULL | 0.000 |
| 12 | root | localhost | NULL | Query | 0 | Init | show processlist | 0.000 |
| 17 | root | test001.colo.sproutsys.com:51990 | NULL | Binlog Dump | 353 | Master has sent all binlog to slave; waiting for binlog to be updated | NULL | 0.000 |
| 19 | system user | | NULL | Slave_IO | 82 | Waiting for master to send event | NULL | 0.000 |
| 20 | system user | | test | Slave_SQL | 26 | Altering table | optimize table foo | 0.000 |
+----+-------------+---------------------------------+------+-------------+------+-----------------------------------------------------------------------+--------------------+----------+
9 rows in set (0.001 sec)
 
MariaDB [(none)]> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: test001
Master_User: root
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: binlog.000002
Read_Master_Log_Pos: 598
Relay_Log_File: zen010-relay-bin.000002
Relay_Log_Pos: 684
Relay_Master_Log_File: binlog.000002
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
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:
Skip_Counter: 0
Exec_Master_Log_Pos: 471
Relay_Log_Space: 1121
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: 9
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 2
Master_SSL_Crl:
Master_SSL_Crlpath:
Using_Gtid: No
Gtid_IO_Pos:
Replicate_Do_Domain_Ids:
Replicate_Ignore_Domain_Ids:
Parallel_Mode: conservative
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Altering table
Slave_DDL_Groups: 1
Slave_Non_Transactional_Groups: 1
Slave_Transactional_Groups: 0
1 row in set (0.000 sec)

Any further details needed, let me know.

Thank You,
Suresh



 Comments   
Comment by Andrei Elkin [ 2020-06-22 ]

sujatha.sivakumar I think it's okay to binlog a killed Query regardless of the # of tables in it and also regardless of the KILL type. We would just state that in the docs. Go to ask serg about this possibility which looks quite harmless to me.

As to no actual SOFT kill, we should open a new ticket for that (it does not look good to reuse the current one imo).

Comment by Sujatha Sivakumar (Inactive) [ 2020-12-21 ]

Hello Andrei,

Please review the fix for MDEV-22530.
MDEV-22530 fix is implemented on top of MDEV-17515 fix.

https://github.com/MariaDB/server/commit/44eb746c226d3eabe93d476790bb0c6bb30106b2

Please review top two commits:

1. commit 44eb746c226d3eabe93d476790bb0c6bb30106b2
MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server.

2. commit 502a6b9b3ce119f507cb8ccc9ec034a9953ad3cc
MDEV-17515: GTID Replication in optimistic mode deadlock

Thank you.

Comment by Sachin Setiya (Inactive) [ 2021-05-11 ]

OK to push

Comment by Sujatha Sivakumar (Inactive) [ 2021-05-17 ]

MDEV-22530 and MDEV-17515 are related. MDEV-22530's fix is implemented on MDEV-17515's fix.

Hence both are tested and pushed together.

10.3: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.3-sujatha
====
commit 07da206ccd21080351363a2c1f080320367c52bb (HEAD -> 10.3, origin/bb-10.3-sujatha)
MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server.

10.3 cherry-pick testing.

commit e683e8c010bd2ffa9415857828e89f94b9ac0550
MDEV-17515: GTID Replication in optimistic mode deadlock

10.3 cherry-pick testing.

10.4: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.4-sujatha
====
commit 0f34165ec1427eccbf18db9f71744537fe6a1354 (HEAD -> 10.4, origin/bb-10.4-sujatha)
MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server.

10.4 cherry-pick testing.

commit 4169e6571c342b57a3ce89e7ae45328c06beb788
MDEV-17515: GTID Replication in optimistic mode deadlock

10.4 cherry-pick testing.

Merge conflicts addressed.
Result file re-recorded.

10.5: http://buildbot.askmonty.org/buildbot/grid?category=main&branch=bb-10.5-sujatha
====
commit 0f9598100aa37f48e8eb93669396e9fac37c493a (HEAD -> 10.5, origin/bb-10.5-sujatha)
MDEV-22530: Aborting OPTIMIZE TABLE still logs in binary log and replicates to the Slave server.

10.5 cherry-pick testing.

No Merge conflicts

commit f0c220898fbe8f58393d386aa0cb6da6b7cedf9f
MDEV-17515: GTID Replication in optimistic mode deadlock

10.5 cherry-pick testing.

Moved changes to log_event_server.cc

Generated at Thu Feb 08 09:15:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.