savepoints and replication
Affects | Status | Importance | Assigned to | Milestone | ||
---|---|---|---|---|---|---|
Percona Server moved to https://jira.percona.com/projects/PS | Status tracked in 5.7 | |||||
5.6 |
Incomplete
|
High
|
Vlad Lesin | |||
5.7 |
Incomplete
|
High
|
Vlad Lesin |
Bug Description
This bug report is a summary about savepoints in replication.
There are two bugs reported earlier: https:/
The full description of bug #1438990 and the way to fix it can be found here https:/
The full description of bug #1464468 is here: https:/
The suggested fixes here also fixes both bugs.
After fixing these two bugs we have the following issues with binary logs:
#### Consider Simplified testcase.
--delimiter |
CREATE TRIGGER t_insert_trig AFTER INSERT ON t
FOR EACH ROW
BEGIN
END |
--delimiter ;
INSERT INTO t VALUES (2);
INSERT INTO t VALUES (3);
master-bin.000001 # Query # # BEGIN
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Write_rows # # table_id: #
master-bin.000001 # Query # # SAVEPOINT `savepoint_1`
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Xid # # COMMIT /* XID */
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Query # # SAVEPOINT `savepoint_1`
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
There are two issues in master binary log:
1) The absence of STMT_END_F
2) The absence of "COMMIT"
#### 1) The absence of STMT_END_F
Consider the first issue. The question is why slave binary log has STMT_END_F?
See Query_log_
#0 binlog_
at ./sql/binlog.cc:367
#1 0x0000000000a3e276 in MYSQL_BIN_
this=0x185cdc0 <mysql_bin_log>, thd=0x7fffbc000a40, event=0x0,
is_
at ./sql/binlog.
#2 0x0000000000a469af in THD::binlog_
this=
at ./sql/binlog.
#3 0x0000000000775bd7 in THD::binlog_
this=
at ./sql/sql_
#4 0x0000000000763155 in close_thread_tables (thd=0x7fffbc00
at ./sql/sql_
#5 0x0000000000a7c3a5 in Relay_log_
this=0x1bb2140, thd=0x7fffbc000a40)
at ./sql/rpl_
#6 0x0000000000a0f54d in Query_log_
this=
query_
at ./sql/log_
#7 0x0000000000a0f05f in Query_log_
this=
at ./sql/log_
How to fix?
Actually there is no need to fix it. Here is the comment in MYSQL_BIN_
/*
We only end the statement if we are in a top-level statement. If
we are inside a stored function, we do not end the statement since
this will close all tables on the slave.
*/
So STMT_END_F flag absence in event before SAVEPOINT in trigger or SP is a correct behavior for master. From slave's point of view STMT_END_F flag presence is correct too because there is no trigger or SP call in slave thread. There is just events applying.
#### 2) The absence of "COMMIT"
Consider the second issue.
If we add new event between SAVEPOINT and the end of trigger body then we will see the following binlog:
--delimiter |
CREATE TRIGGER t_insert_trig AFTER INSERT ON t
FOR EACH ROW
BEGIN
SAVEPOINT savepoint_1;
INSERT INTO `t2` VALUES (NEW.f1);
END |
--delimiter ;
INSERT INTO `t` VALUES (2);
INSERT INTO `t` VALUES (3);
master-bin.000001 # Query # # BEGIN
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Table_map # # table_id: # (test.t2)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Query # # SAVEPOINT `savepoint_1`
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Table_map # # table_id: # (test.t2)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Xid # # COMMIT /* XID */
master-bin.000001 # Query # # BEGIN
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Table_map # # table_id: # (test.t2)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Query # # SAVEPOINT `savepoint_1`
master-bin.000001 # Table_map # # table_id: # (test.t)
master-bin.000001 # Table_map # # table_id: # (test.t2)
master-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
master-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t2)
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Query # # SAVEPOINT `savepoint_1`
slave-bin.000001 # Table_map # # table_id: # (test.t2)
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
slave-bin.000001 # Query # # BEGIN
slave-bin.000001 # Table_map # # table_id: # (test.t2)
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Query # # SAVEPOINT `savepoint_1`
slave-bin.000001 # Table_map # # table_id: # (test.t2)
slave-bin.000001 # Table_map # # table_id: # (test.t)
slave-bin.000001 # Write_rows # # table_id: # flags: STMT_END_F
slave-bin.000001 # Xid # # COMMIT /* XID */
The questions is why we have "COMMIT" in this case?
It's because write_locked_
(gdb) bt
#0 binlog_
at ./sql/binlog.
#1 0x0000000000a440aa in THD::binlog_
table=
at ./sql/binlog.
#2 0x0000000000645147 in write_locked_
at ./sql/handler.
#3 0x0000000000645242 in binlog_log_row (table=
before_
log_
at ./sql/handler.
#4 0x0000000000645852 in handler:
buf=
at ./sql/handler.
#5 0x00000000007b9006 in write_record (thd=0x1cbd4e0, table=0x7fffa40
info=
at ./sql/sql_
#6 0x00000000007b6d1e in mysql_insert (thd=0x1cbd4e0,
table_
update_
at ./sql/sql_
#7 0x00000000007d87de in mysql_execute_
at ./sql/sql_
#8 0x00000000007e0af8 in mysql_parse (thd=0x1cbd4e0,
rawbuf=
parser_
at ./sql/sql_
#9 0x00000000007d2a70 in dispatch_command (command=COM_QUERY, thd=0x1cbd4e0,
packet=
at ./sql/sql_
#10 0x00000000007d1925 in do_command (thd=0x1cbd4e0)
at ./sql/sql_
#11 0x000000000079b0ff in do_handle_
at ./sql/sql_
#12 0x000000000079ab87 in handle_
at ./sql/sql_
#13 0x0000000000da33ce in pfs_spawn_thread (arg=0x1c3db40)
at ./storage/
#14 0x00007ffff737d182 in start_thread (arg=0x7ffff029
at pthread_
#15 0x00007ffff688a47d in clone ()
at ../sysdeps/
Why binlog_
It's because the number of tables in binary log table map is not zero:
(gdb) bt
#0 write_locked_
at ./sql/handler.
#1 0x0000000000645242 in binlog_log_row (table=
before_
log_
at ./sql/handler.
#2 0x0000000000645852 in handler:
buf=
at ./sql/handler.
#3 0x00000000007b9006 in write_record (thd=0x1cbbfd0, table=0x7fffb00
info=
at ./sql/sql_
#4 0x00000000007b6d1e in mysql_insert (thd=0x1cbbfd0,
table_
update_
at ./sql/sql_
#5 0x00000000007d87de in mysql_execute_
at ./sql/sql_
#6 0x00000000007e0af8 in mysql_parse (thd=0x1cbbfd0,
rawbuf=
parser_
at ./sql/sql_
---Type <return> to continue, or q <return> to quit---
#7 0x00000000007d2a70 in dispatch_command (command=COM_QUERY, thd=0x1cbbfd0,
packet=
at ./sql/sql_
#8 0x00000000007d1925 in do_command (thd=0x1cbbfd0)
at ./sql/sql_
#9 0x000000000079b0ff in do_handle_
at ./sql/sql_
#10 0x000000000079ab87 in handle_
at ./sql/sql_
#11 0x0000000000da33ce in pfs_spawn_thread (arg=0x1c30f00)
at ./storage/
#12 0x00007ffff737d182 in start_thread (arg=0x7ffff029
at pthread_
#13 0x00007ffff688a47d in clone ()
at ../sysdeps/
(gdb) n
7459 DBUG_PRINT("enter", ("thd: 0x%lx thd->lock: 0x%lx "
(gdb)
7463 DBUG_PRINT("debug", ("get_binlog_
(gdb)
7465 if (force || (thd->get_
(gdb)
7518 DBUG_RETURN(0);
(gdb) p force
$1 = false
(gdb) p thd->get_
$2 = 1
How is this number zeroed out for the case if there is some event between SAVEPOINT and trigger body end?
(gdb) bt
#0 THD::clear_
at ./sql/sql_
#1 0x0000000000a4908a in binlog_
this=
at ./sql/binlog.cc:499
#2 0x0000000000a33d57 in binlog_
thd=0x1cbcd80, end_event=
at ./sql/binlog.
#3 0x0000000000a41c2b in MYSQL_BIN_
this=0x185cdc0 <mysql_bin_log>, thd=0x1cbcd80, all=false)
at ./sql/binlog.
#4 0x0000000000638429 in ha_commit_trans (thd=0x1cbcd80, all=false,
ignore_
at ./sql/handler.
#5 0x00000000008ab4ee in trans_commit_stmt (thd=0x1cbcd80)
at ./sql/transacti
#6 0x00000000007dd7c5 in mysql_execute_
at ./sql/sql_
#7 0x00000000007e0af8 in mysql_parse (thd=0x1cbcd80,
rawbuf=
parser_
at ./sql/sql_
#8 0x00000000007d2a70 in dispatch_command (command=COM_QUERY, thd=0x1cbcd80,
---Type <return> to continue, or q <return> to quit---
packet=
at ./sql/sql_
#9 0x00000000007d1925 in do_command (thd=0x1cbcd80)
at ./sql/sql_
#10 0x000000000079b0ff in do_handle_
at ./sql/sql_
#11 0x000000000079ab87 in handle_
at ./sql/sql_
#12 0x0000000000da33ce in pfs_spawn_thread (arg=0x1c67750)
at ./storage/
#13 0x00007ffff737d182 in start_thread (arg=0x7ffff029
at pthread_
#14 0x00007ffff688a47d in clone ()
at ../sysdeps/
So we have the situation when binlog_
How to fix?
binlog_
1)
binlog_
MYSQL_BIN_
THD::binlog_
MYSQL_BIN_
binlog_
2)
binlog_
MYSQL_BIN_
THD::binlog_
MYSQL_BIN_
binlog_
ha_savepoint()
The difference between this two ways is that binlog_
So the fix is in invoking THD::clear_
Note: this fix will also fix this bug https:/
This can be explained so that THD::binlog_
(gdb) bt
#0 write_locked_
at ./sql/handler.
#1 0x00000000006451e0 in binlog_log_row (table=
before_
log_
at ./sql/handler.
#2 0x00000000006457f0 in handler:
buf=
at ./sql/handler.
#3 0x00000000007b8fa2 in write_record (thd=0x1ca4810, table=0x7fffac0
info=
at ./sql/sql_
#4 0x00000000007b6cba in mysql_insert (thd=0x1ca4810,
table_
update_
at ./sql/sql_
#5 0x00000000007d877a in mysql_execute_
at ./sql/sql_
#6 0x00000000007e0a94 in mysql_parse (thd=0x1ca4810,
rawbuf=
parser_
at ./sql/sql_
---Type <return> to continue, or q <return> to quit---
#7 0x00000000007d2a0c in dispatch_command (command=COM_QUERY, thd=0x1ca4810,
packet=
at ./sql/sql_
#8 0x00000000007d18c1 in do_command (thd=0x1ca4810)
at ./sql/sql_
#9 0x000000000079b09b in do_handle_
at ./sql/sql_
#10 0x000000000079ab23 in handle_
at ./sql/sql_
#11 0x0000000000da336a in pfs_spawn_thread (arg=0x1c17170)
at ./storage/
#12 0x00007ffff737d182 in start_thread (arg=0x7ffff035
at pthread_
#13 0x00007ffff688a47d in clone ()
at ../sysdeps/
Note: This will also fix this bug https:/
Changed in percona-server: | |
assignee: | nobody → Vlad Lesin (vlad-lesin) |
description: | updated |
tags: | added: i51914 |
I see the following output from the test case on upstream 5.6.27:
openxs@ ao756:~ /dbs/5. 6/mysql- test$ cat suite/rpl/t/bug1483251.test have_binlog_ format_ row.inc master- slave.inc
--source include/
--source include/
CREATE TABLE `t` (
`f1` int(10) unsigned NOT NULL,
PRIMARY KEY (`f1`)
) ENGINE=InnoDB;
--delimiter |
SAVEPOINT savepoint_1;
SET @a = 10;
CREATE TRIGGER t_insert_trig AFTER INSERT ON t
FOR EACH ROW
BEGIN
END |
--delimiter ;
INSERT INTO t VALUES (2);
INSERT INTO t VALUES (3);
--source include/ show_binlog_ events. inc
SELECT * FROM t;
--source include/ sync_slave_ sql_with_ master. inc
--connection slave show_binlog_ events. inc
SELECT * FROM t;
--source include/
--connection master
DROP TABLE t;
--source include/rpl_end.inc
openxs@ ao756:~ /dbs/5. 6/mysql- test$ ./mtr --suite=rpl bug1483251 dbs/5.6/ bin/mysqld (mysqld 5.6.27) starting as process 25121 ...
Logging: ./mtr --suite=rpl bug1483251
2015-11-17 09:55:23 0 [Note] /home/openxs/
2015-11-17 09:55:23 25121 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)
2015-11-17 09:55:23 25121 [Warning] Buffered warning: Changed limits: table_open_cache: 431 (requested 2000)
2015-11-17 09:55:23 25121 [Note] Plugin 'FEDERATED' is disabled. openxs/ dbs/5.6/ mysql-test/ var'...
2015-11-17 09:55:23 25121 [Note] Binlog end
2015-11-17 09:55:23 25121 [Note] Shutting down plugin 'CSV'
2015-11-17 09:55:23 25121 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.27
Checking supported features...
- SSL connections supported
Collecting tests...
- adding combinations for rpl
Checking leftover processes...
Removing old var directory...
Creating var directory '/home/
Installing system database...
======= ======= ======= ======= ======= ======= ======= ======= ======= ======= ======= =
TEST RESULT TIME (ms) or COMMENT ------- ------- ------- ------- ------- ------- ------- ------- ------- ----
-------
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009 format= 'mixed'
rpl.bug1483251 'mix' [ skipped ] Doesn't support --binlog-
rpl.bug1483251 'row' [ fail ]
Test ended at 2015-11-17 09:55:37
CURRENT_TEST: rpl.bug1483251 dbs/5.6/ mysql-test/ suite/rpl/ r/bug1483251.result 2015-11-17 10:48:36.487992561 +0300 dbs/5.6/ mysql-test/ var/log/bug1483251.reject 2015-11-17 10:55:37.663973783 +0300 master- slave.inc
--- /home/openxs/
+++ /home/openxs/
@@ -0,0 +1,72 @@
+include/
+Warnings:
+Note #### Sending passwords in plain text without SSL/TLS is extremely insecure.
+Note #### 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.
+[connection master]
+CREATE TABLE `t` (
+`f1` int(10) unsigned NOT NULL,
+PRIMARY KEY (`f1`)
+) ENGINE=InnoDB;
+CREATE TRIGGER t_insert_trig AFTER INSERT ON t
+FOR EACH ROW
+BEGIN
+SAVEPOINT savepoint_1;
+SET @a = 10;
+END |
+INSERT INTO t VALUES (2);
+INSERT INTO t VALUES (3);
+include/show...