From bd25e296b107c6ec14bf0a89327a46190069e0b6 Mon Sep 17 00:00:00 2001 From: Abhinav Sharma Date: Mon, 26 Feb 2018 15:51:30 -0800 Subject: [PATCH] Optimize Rows_query_log_event logging to save disk space Summary: A separate event for trx metadata was causing an unreasonable increase in binlog size. Also, now we're not writing rows query event if there are no comments in the query and `log_only_query_comments` is enabled Reviewed By: anirbanr-fb Differential Revision: D7002217 fbshipit-source-id: 1c3ab92 --- .../r/binlog_row_mysqlbinlog_verbose.result | 2 + .../r/binlog_row_query_log_events.result | 2 + .../t/binlog_row_mysqlbinlog_verbose.test | 2 + .../binlog/t/binlog_row_query_log_events.test | 2 + .../rpl/include/binlog_trx_meta_data.inc | 62 ++++ .../suite/rpl/r/binlog_db_metadata.result | 64 ++--- .../suite/rpl/r/binlog_trx_meta_data.result | 14 +- .../rpl/r/binlog_trx_meta_data_rbr.result | 69 +++++ .../rpl/r/rpl_log_only_query_comments.result | 14 +- .../suite/rpl/t/binlog_trx_meta_data.test | 59 +--- .../suite/rpl/t/binlog_trx_meta_data_rbr.test | 56 ++++ .../rpl/t/rpl_row_ignorable_event-master.opt | 2 +- .../rpl/t/rpl_row_ignorable_event-slave.opt | 2 +- sql/binlog.cc | 272 +++++++++--------- sql/log_event.cc | 28 +- sql/log_event.h | 16 +- sql/rpl_slave.cc | 5 +- sql/sql_binlog.cc | 5 +- sql/sql_class.h | 7 + 19 files changed, 430 insertions(+), 253 deletions(-) create mode 100644 mysql-test/suite/rpl/include/binlog_trx_meta_data.inc create mode 100644 mysql-test/suite/rpl/r/binlog_trx_meta_data_rbr.result create mode 100644 mysql-test/suite/rpl/t/binlog_trx_meta_data_rbr.test diff --git a/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result b/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result index 2650a5cf7d9a..bb20abb1d32e 100644 --- a/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result +++ b/mysql-test/suite/binlog/r/binlog_row_mysqlbinlog_verbose.result @@ -160,8 +160,10 @@ stmt ### @1=2 drop table raw_binlog_rows; SET @@SESSION.BINLOG_ROWS_QUERY_LOG_EVENTS = 1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = 0; CREATE TABLE t1 (a VARCHAR(50)); INSERT INTO t1 VALUES (" GRANT ALL ON *.* TO 'batman'/*!*/; ")| DROP TABLE t1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = DEFAULT; diff --git a/mysql-test/suite/binlog/r/binlog_row_query_log_events.result b/mysql-test/suite/binlog/r/binlog_row_query_log_events.result index c02a685b3f48..12940af1838c 100644 --- a/mysql-test/suite/binlog/r/binlog_row_query_log_events.result +++ b/mysql-test/suite/binlog/r/binlog_row_query_log_events.result @@ -1,5 +1,7 @@ SET @@SESSION.BINLOG_ROWS_QUERY_LOG_EVENTS = 1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = 0; CREATE TABLE t1 (a VARCHAR(256)); INSERT INTO t1 VALUES ('aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa'); include/assert.inc [Logged query must match the one issued.] DROP TABLE t1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = DEFAULT; diff --git a/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test b/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test index dfa080ac53f0..3ec420e4b7b8 100644 --- a/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test +++ b/mysql-test/suite/binlog/t/binlog_row_mysqlbinlog_verbose.test @@ -90,6 +90,7 @@ drop table raw_binlog_rows; # the multi-line original statement are properly escaped to prevent from # being executed. SET @@SESSION.BINLOG_ROWS_QUERY_LOG_EVENTS = 1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = 0; CREATE TABLE t1 (a VARCHAR(50)); --let $binlog_start_position= query_get_value("SHOW MASTER STATUS", Position, 1) @@ -140,4 +141,5 @@ END_OF_FILE # Clean up DROP TABLE t1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = DEFAULT; --remove_file $TMP_FILE diff --git a/mysql-test/suite/binlog/t/binlog_row_query_log_events.test b/mysql-test/suite/binlog/t/binlog_row_query_log_events.test index 72e07eb9e4c9..8dff6b8f2dc3 100644 --- a/mysql-test/suite/binlog/t/binlog_row_query_log_events.test +++ b/mysql-test/suite/binlog/t/binlog_row_query_log_events.test @@ -6,6 +6,7 @@ # Check that queries with more than 255 characters are not truncated # when stored on Rows_query_log_events. SET @@SESSION.BINLOG_ROWS_QUERY_LOG_EVENTS = 1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = 0; CREATE TABLE t1 (a VARCHAR(256)); --let $as= `SELECT REPEAT('a', 256)` @@ -29,3 +30,4 @@ if (!`SELECT COUNT(*) = 0 OR VARIABLE_VALUE != 'ON' FROM INFORMATION_SCHEMA.GLOB # Clean up DROP TABLE t1; +SET @@GLOBAL.LOG_ONLY_QUERY_COMMENTS = DEFAULT; diff --git a/mysql-test/suite/rpl/include/binlog_trx_meta_data.inc b/mysql-test/suite/rpl/include/binlog_trx_meta_data.inc new file mode 100644 index 000000000000..0d5105c24b44 --- /dev/null +++ b/mysql-test/suite/rpl/include/binlog_trx_meta_data.inc @@ -0,0 +1,62 @@ +# Init +connection master; +flush logs; +let $master_last_log = query_get_value("SHOW MASTER STATUS", "File", 1); +eval purge binary logs to '$master_last_log'; +connection slave; +flush logs; +let $slave_last_log = query_get_value("SHOW MASTER STATUS", "File", 1); +eval purge binary logs to '$slave_last_log'; + +# Generate load +connection master; +disable_result_log; +disable_query_log; +create table t1(a int auto_increment primary key) engine=innodb; +# the following loop will generate 300 meta data events, 1 for each statement +# the total number of meta data events will be 301, +1 for create stmt above +let $iter= 10; +while ($iter > 0) +{ + begin; + eval /*insert*/insert into t1 values(); + eval /*update*/update t1 set a= a + 1; + /*delete*/delete from t1; + commit; + dec $iter; +} +enable_result_log; +enable_query_log; +sync_slave_with_master; + +# Check binlogs for meta data +connection master; +disable_query_log; +let $MYSQLD_DATADIR = `select @@datadir`; +let $MYSQLD_SECURE_FILE_DIR = `select @@secure_file_priv`; +exec $MYSQL_BINLOG -v -v $MYSQLD_DATADIR/master-bin.0* | grep "::TRX_META_DATA::" | sed 's/\"[0-9]*\"/ts/g' > $MYSQLD_SECURE_FILE_DIR/meta_data.dat; +set sql_log_bin=0; +create table test.meta_data(meta text); +eval load data infile '$MYSQLD_SECURE_FILE_DIR/meta_data.dat' into table test.meta_data; +select meta, count(*) from test.meta_data group by meta; +drop table test.meta_data; +set sql_log_bin=1; +remove_file $MYSQLD_SECURE_FILE_DIR/meta_data.dat; + +connection slave; +let $MYSQLD_DATADIR = `select @@datadir`; +let $MYSQLD_SECURE_FILE_DIR = `select @@secure_file_priv`; +exec $MYSQL_BINLOG -v -v $MYSQLD_DATADIR/slave-bin.0* | grep "::TRX_META_DATA::" | sed 's/\"[0-9]*\"/ts/g' > $MYSQLD_SECURE_FILE_DIR/meta_data.dat; +set sql_log_bin=0; +create table test.meta_data(meta text); +eval load data infile '$MYSQLD_SECURE_FILE_DIR/meta_data.dat' into table test.meta_data; +select meta, count(*) from test.meta_data group by meta; +drop table test.meta_data; +set sql_log_bin=1; +remove_file $MYSQLD_SECURE_FILE_DIR/meta_data.dat; +enable_query_log; + +# Cleanup +connection master; +drop table t1; +sync_slave_with_master; diff --git a/mysql-test/suite/rpl/r/binlog_db_metadata.result b/mysql-test/suite/rpl/r/binlog_db_metadata.result index a03601497fd4..c5a1c393bf1e 100644 --- a/mysql-test/suite/rpl/r/binlog_db_metadata.result +++ b/mysql-test/suite/rpl/r/binlog_db_metadata.result @@ -34,39 +34,39 @@ use test4; create table t1 (a int primary key, b char(8)); insert into t1 values(1, 'a'); insert into t1 values(2, 'b'); -# /*::TRX_META_DATA::{"timestamps":[ts]}*/ -# /*::TRX_META_DATA::{"timestamps":[ts]}*/ -# /*::TRX_META_DATA::{"timestamps":[ts]}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ -# /*::TRX_META_DATA::{"timestamps":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ +# /*::TRX_META_DATA::{"ts":[ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test2_shard","replicaset":"test2_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard","replicaset":"test3_replicaset"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ +# /*::TRX_META_DATA::{"ts":[ts],"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4"}*/ include/sync_slave_sql_with_master.inc -# /*::TRX_META_DATA::{"timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","timestamps":[ts,ts]}*/ -# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","timestamps":[ts,ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test2_shard","replicaset":"test2_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard","replicaset":"test3_replicaset","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"test3_shard_updated","replicaset":"test3_replicaset_updated","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","ts":[ts,ts]}*/ +# /*::TRX_META_DATA::{"shard":"newly_added_shard_for_test4","replicaset":"new_replicaset_for_test4","ts":[ts,ts]}*/ use test; drop table if exists t1; drop database if exists test2; diff --git a/mysql-test/suite/rpl/r/binlog_trx_meta_data.result b/mysql-test/suite/rpl/r/binlog_trx_meta_data.result index 3692b74333c5..ae771f07fb07 100644 --- a/mysql-test/suite/rpl/r/binlog_trx_meta_data.result +++ b/mysql-test/suite/rpl/r/binlog_trx_meta_data.result @@ -3,15 +3,17 @@ 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] -set @save.binlog_trx_meta_data= @@global.binlog_trx_meta_data; set @@global.binlog_trx_meta_data= true; -set @save.binlog_trx_meta_data= @@global.binlog_trx_meta_data; set @@global.binlog_trx_meta_data= true; +flush logs; +purge binary logs to 'master-bin.000002'; +flush logs; +purge binary logs to 'slave-bin.000002'; meta count(*) -# /*::TRX_META_DATA::{"timestamps":[ts]}*/ 301 +# /*::TRX_META_DATA::{"ts":[ts]}*/ 31 meta count(*) -# /*::TRX_META_DATA::{"timestamps":[ts,ts]}*/ 301 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ 31 drop table t1; -set @@global.binlog_trx_meta_data= @save.binlog_trx_meta_data; -set @@global.binlog_trx_meta_data= @save.binlog_trx_meta_data; +set @@global.binlog_trx_meta_data= default; +set @@global.binlog_trx_meta_data= default; include/rpl_end.inc diff --git a/mysql-test/suite/rpl/r/binlog_trx_meta_data_rbr.result b/mysql-test/suite/rpl/r/binlog_trx_meta_data_rbr.result new file mode 100644 index 000000000000..6eefdd499e78 --- /dev/null +++ b/mysql-test/suite/rpl/r/binlog_trx_meta_data_rbr.result @@ -0,0 +1,69 @@ +include/master-slave.inc +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] +set @@global.binlog_trx_meta_data= true; +set @@global.binlog_trx_meta_data= true; +set @@session.binlog_rows_query_log_events= OFF; +set @@global.binlog_rows_query_log_events= OFF; +include/stop_slave.inc +include/start_slave.inc +flush logs; +purge binary logs to 'master-bin.000002'; +flush logs; +purge binary logs to 'slave-bin.000002'; +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts]}*/ 31 +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ 31 +drop table t1; +set @@session.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= OFF; +set @@global.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= OFF; +include/stop_slave.inc +include/start_slave.inc +flush logs; +purge binary logs to 'master-bin.000003'; +flush logs; +purge binary logs to 'slave-bin.000003'; +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts]}*/ 1 +# /*::TRX_META_DATA::{"ts":[ts]}*//*delete*/delete from t1 10 +# /*::TRX_META_DATA::{"ts":[ts]}*//*insert*/insert into t1 values() 10 +# /*::TRX_META_DATA::{"ts":[ts]}*//*update*/update t1 set a= a + 1 10 +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ 1 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*delete*/delete from t1 10 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*insert*/insert into t1 values() 10 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*update*/update t1 set a= a + 1 10 +drop table t1; +set @@session.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= ON; +set @@global.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= ON; +include/stop_slave.inc +include/start_slave.inc +flush logs; +purge binary logs to 'master-bin.000004'; +flush logs; +purge binary logs to 'slave-bin.000004'; +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts]}*/ 1 +# /*::TRX_META_DATA::{"ts":[ts]}*//*delete*/ 10 +# /*::TRX_META_DATA::{"ts":[ts]}*//*insert*/ 10 +# /*::TRX_META_DATA::{"ts":[ts]}*//*update*/ 10 +meta count(*) +# /*::TRX_META_DATA::{"ts":[ts,ts]}*/ 1 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*delete*/ 10 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*insert*/ 10 +# /*::TRX_META_DATA::{"ts":[ts,ts]}*//*update*/ 10 +drop table t1; +set @@global.binlog_trx_meta_data= default; +set @@session.binlog_rows_query_log_events= default; +set @@global.log_only_query_comments= default; +set @@global.binlog_trx_meta_data= default; +set @@global.binlog_rows_query_log_events= default; +set @@global.log_only_query_comments= default; +include/rpl_end.inc diff --git a/mysql-test/suite/rpl/r/rpl_log_only_query_comments.result b/mysql-test/suite/rpl/r/rpl_log_only_query_comments.result index 81cba1e6f39f..4d2f102f048e 100644 --- a/mysql-test/suite/rpl/r/rpl_log_only_query_comments.result +++ b/mysql-test/suite/rpl/r/rpl_log_only_query_comments.result @@ -9,20 +9,14 @@ insert into t1 values(1); /*Comment test */ insert into t1 values(2); /*Comment test */ /* Comment test*/ insert into t1 values(4); drop table t1; -#010909 4:46:40 server id 1 end_log_pos 325 Rows_query -# insert into t1 values(1) --- -#010909 4:46:40 server id 1 end_log_pos 578 Rows_query +#010909 4:46:40 server id 1 end_log_pos 534 Rows_query # /*Comment test */ -- -#010909 4:46:40 server id 1 end_log_pos 851 Rows_query +#010909 4:46:40 server id 1 end_log_pos 807 Rows_query # /*Comment test */ /* Comment test*/ -#010909 4:46:40 server id 1 end_log_pos 316 Rows_query -# insert into t1 values(1) --- -#010909 4:46:40 server id 1 end_log_pos 551 Rows_query +#010909 4:46:40 server id 1 end_log_pos 507 Rows_query # /*Comment test */ -- -#010909 4:46:40 server id 1 end_log_pos 806 Rows_query +#010909 4:46:40 server id 1 end_log_pos 762 Rows_query # /*Comment test */ /* Comment test*/ include/rpl_end.inc diff --git a/mysql-test/suite/rpl/t/binlog_trx_meta_data.test b/mysql-test/suite/rpl/t/binlog_trx_meta_data.test index 020ff43ac0d9..5a4ca0065d40 100644 --- a/mysql-test/suite/rpl/t/binlog_trx_meta_data.test +++ b/mysql-test/suite/rpl/t/binlog_trx_meta_data.test @@ -1,69 +1,18 @@ source include/master-slave.inc; +source include/not_binlog_format_row.inc; # we have binlog_trx_meta_data_rbr.test for this # Enable trx meta data connection master; -set @save.binlog_trx_meta_data= @@global.binlog_trx_meta_data; set @@global.binlog_trx_meta_data= true; - connection slave; -set @save.binlog_trx_meta_data= @@global.binlog_trx_meta_data; set @@global.binlog_trx_meta_data= true; -# Generate load -connection master; -disable_result_log; -disable_query_log; -create table t1(a int) engine=innodb; -# the following loop will generate 300 meta data events, 1 for each statement -# the total number of meta data events will be 301, +1 for create stmt above -let $iter= 100; -while ($iter > 0) -{ - begin; - eval insert into t1 values($iter); - eval update t1 set a= $iter + 1; - delete from t1; - commit; - dec $iter; -} -enable_result_log; -enable_query_log; -sync_slave_with_master; - -# Check binlogs for meta data -connection master; -disable_query_log; -let $MYSQLD_DATADIR = `select @@datadir`; -let $MYSQLD_SECURE_FILE_DIR = `select @@secure_file_priv`; -exec $MYSQL_BINLOG -v -v $MYSQLD_DATADIR/master-bin.0* | grep "::TRX_META_DATA::" | sed 's/\"[0-9]*\"/ts/g' > $MYSQLD_SECURE_FILE_DIR/meta_data.dat; -set sql_log_bin=0; -create table test.meta_data(meta text); -eval load data infile '$MYSQLD_SECURE_FILE_DIR/meta_data.dat' into table test.meta_data; -select meta, count(*) from test.meta_data; -drop table test.meta_data; -set sql_log_bin=1; -remove_file $MYSQLD_SECURE_FILE_DIR/meta_data.dat; - -connection slave; -let $MYSQLD_DATADIR = `select @@datadir`; -let $MYSQLD_SECURE_FILE_DIR = `select @@secure_file_priv`; -exec $MYSQL_BINLOG -v -v $MYSQLD_DATADIR/slave-bin.0* | grep "::TRX_META_DATA::" | sed 's/\"[0-9]*\"/ts/g' > $MYSQLD_SECURE_FILE_DIR/meta_data.dat; -set sql_log_bin=0; -create table test.meta_data(meta text); -eval load data infile '$MYSQLD_SECURE_FILE_DIR/meta_data.dat' into table test.meta_data; -select meta, count(*) from test.meta_data; -drop table test.meta_data; -set sql_log_bin=1; -remove_file $MYSQLD_SECURE_FILE_DIR/meta_data.dat; -enable_query_log; +source suite/rpl/include/binlog_trx_meta_data.inc; # Cleanup connection master; -drop table t1; -sync_slave_with_master; +set @@global.binlog_trx_meta_data= default; connection slave; -set @@global.binlog_trx_meta_data= @save.binlog_trx_meta_data; -connection master; -set @@global.binlog_trx_meta_data= @save.binlog_trx_meta_data; +set @@global.binlog_trx_meta_data= default; source include/rpl_end.inc; diff --git a/mysql-test/suite/rpl/t/binlog_trx_meta_data_rbr.test b/mysql-test/suite/rpl/t/binlog_trx_meta_data_rbr.test new file mode 100644 index 000000000000..1c9d485f9395 --- /dev/null +++ b/mysql-test/suite/rpl/t/binlog_trx_meta_data_rbr.test @@ -0,0 +1,56 @@ +source include/master-slave.inc; +source include/have_binlog_format_row.inc; + +# Enable trx meta data +connection master; +set @@global.binlog_trx_meta_data= true; +connection slave; +set @@global.binlog_trx_meta_data= true; + + +# Case 1: binlog_rows_query_log_events= OFF +connection master; +set @@session.binlog_rows_query_log_events= OFF; +connection slave; +set @@global.binlog_rows_query_log_events= OFF; +source include/stop_slave.inc; +source include/start_slave.inc; + +source suite/rpl/include/binlog_trx_meta_data.inc; + + +# Case 2: binlog_rows_query_log_events= ON and log_only_query_comments= OFF +connection master; +set @@session.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= OFF; +connection slave; +set @@global.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= OFF; +source include/stop_slave.inc; +source include/start_slave.inc; + +source suite/rpl/include/binlog_trx_meta_data.inc; + + +# Case 3: binlog_rows_query_log_events= ON and log_only_query_comments= ON +connection master; +set @@session.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= ON; +connection slave; +set @@global.binlog_rows_query_log_events= ON; +set @@global.log_only_query_comments= ON; +source include/stop_slave.inc; +source include/start_slave.inc; + +source suite/rpl/include/binlog_trx_meta_data.inc; + +connection master; +set @@global.binlog_trx_meta_data= default; +set @@session.binlog_rows_query_log_events= default; +set @@global.log_only_query_comments= default; +connection slave; +set @@global.binlog_trx_meta_data= default; +set @@global.binlog_rows_query_log_events= default; +set @@global.log_only_query_comments= default; + +source include/rpl_end.inc; diff --git a/mysql-test/suite/rpl/t/rpl_row_ignorable_event-master.opt b/mysql-test/suite/rpl/t/rpl_row_ignorable_event-master.opt index 231bd363a2fd..a8f8c07ce805 100644 --- a/mysql-test/suite/rpl/t/rpl_row_ignorable_event-master.opt +++ b/mysql-test/suite/rpl/t/rpl_row_ignorable_event-master.opt @@ -1 +1 @@ ---binlog-row-event-max-size=512 --binlog-rows-query-log-events=1 +--binlog-row-event-max-size=512 --binlog-rows-query-log-events=1 --log-only-query-comments=0 diff --git a/mysql-test/suite/rpl/t/rpl_row_ignorable_event-slave.opt b/mysql-test/suite/rpl/t/rpl_row_ignorable_event-slave.opt index 64cd5ac2c86f..200bb4e613ad 100644 --- a/mysql-test/suite/rpl/t/rpl_row_ignorable_event-slave.opt +++ b/mysql-test/suite/rpl/t/rpl_row_ignorable_event-slave.opt @@ -1 +1 @@ ---binlog-row-event-max-size=512 --binlog-rows-query-log-events=1 --replicate-ignore-table=test.t4 --replicate-wild-ignore-table=test.t5 +--binlog-row-event-max-size=512 --binlog-rows-query-log-events=1 --replicate-ignore-table=test.t4 --replicate-wild-ignore-table=test.t5 --log-only-query-comments=0 diff --git a/sql/binlog.cc b/sql/binlog.cc index 27465dda1215..56de3154435f 100644 --- a/sql/binlog.cc +++ b/sql/binlog.cc @@ -336,9 +336,6 @@ class binlog_cache_data cache_log.end_of_file= saved_max_binlog_cache_size; } - int write_trx_metadata(THD *thd); - void add_time_metadata(THD *thd, ptree &meta_data_root); - void add_db_metadata(THD *thd, ptree &meta_data_root); int finalize(THD *thd, Log_event *end_event); int flush(THD *thd, my_off_t *bytes, bool *wrote_xid, bool async); int write_event(THD *thd, Log_event *event, @@ -1007,8 +1004,14 @@ int binlog_cache_data::write_event(THD *thd, { // case: write meta data event before the real event // see @opt_binlog_trx_meta_data - if (write_meta_data_event && write_trx_metadata(thd)) - DBUG_RETURN(1); + if (write_meta_data_event) + { + std::string metadata= thd->gen_trx_metadata(); + Rows_query_log_event metadata_ev(thd, metadata.c_str(), + metadata.length()); + if (metadata_ev.write(&cache_log) != 0) + DBUG_RETURN(1); + } DBUG_EXECUTE_IF("simulate_disk_full_at_binlog_cache_write", { DBUG_SET("+d,simulate_no_free_space_error"); }); @@ -1205,131 +1208,6 @@ int gtid_empty_group_log_and_cleanup(THD *thd) DBUG_RETURN(ret); } -/** - This function writes meta data in JSON format as a comment in a rows query - event. - - @see binlog_trx_meta_data - - @param thd The thread whose transaction should be flushed - @return nonzero if an error pops up when writing to the cache. -*/ -int -binlog_cache_data::write_trx_metadata(THD *thd) -{ - DBUG_ENTER("binlog_cache_data::write_trx_metadata"); - DBUG_ASSERT(opt_binlog_trx_meta_data); - - ptree pt; - std::ostringstream buf; - - // case: read existing meta data received from the master - if (thd->rli_slave && !thd->rli_slave->trx_meta_data_json.empty()) - { - std::istringstream is(thd->rli_slave->trx_meta_data_json); - try { - read_json(is, pt); - } catch (std::exception& e) { - // NO_LINT_DEBUG - sql_print_error("Exception while reading meta data: %s, JSON: %s", - e.what(), thd->rli_slave->trx_meta_data_json.c_str()); - DBUG_RETURN(1); - } - // clear existing data - thd->rli_slave->trx_meta_data_json.clear(); - } - - // add things to the meta data - try { - add_time_metadata(thd, pt); - add_db_metadata(thd, pt); - } catch (std::exception& e) { - // NO_LINT_DEBUG - sql_print_error("Exception while adding meta data: %s", e.what()); - DBUG_RETURN(1); - } - - // write meta data with new stuff in the binlog - try { - write_json(buf, pt, false); - } catch (std::exception& e) { - // NO_LINT_DEBUG - sql_print_error("Exception while writing meta data: %s", e.what()); - DBUG_RETURN(1); - } - std::string json = buf.str(); - boost::trim(json); - - std::string comment_str= std::string("/*") - .append(TRX_META_DATA_HEADER) - .append(json) - .append("*/"); - - Rows_query_log_event e(thd, comment_str.c_str(), comment_str.length()); - DBUG_RETURN(write_event(thd, &e)); -} - -/** - This function adds timing information in meta data JSON of rows query event. - - @see binlog_cache_data::write_trx_metadata - - @param thd The thread whose transaction should be flushed - @param meta_data_root Property tree object which represents the JSON -*/ -void -binlog_cache_data::add_time_metadata(THD *thd, ptree &meta_data_root) -{ - DBUG_ENTER("binlog_cache_data::add_time_metadata"); - DBUG_ASSERT(opt_binlog_trx_meta_data); - - // get existing timestamps - ptree timestamps= meta_data_root.get_child("timestamps", ptree()); - - // add our timestamp to the array - ptree timestamp; - ulonglong millis= - std::chrono::duration_cast - (std::chrono::system_clock::now().time_since_epoch()).count(); - timestamp.put("", millis); - timestamps.push_back(std::make_pair("", timestamp)); - - // update timestamps in root - meta_data_root.erase("timestamps"); - meta_data_root.add_child("timestamps", timestamps); - - DBUG_VOID_RETURN; -} - -void binlog_cache_data::add_db_metadata(THD *thd, ptree &meta_data_root) -{ - DBUG_ENTER("binlog_cache_data::add_db_meta_data"); - DBUG_ASSERT(opt_binlog_trx_meta_data); - - if (!thd->db_metadata.empty()) - { - ptree db_metadata_root; - mysql_mutex_lock(&thd->LOCK_db_metadata); - std::istringstream is(thd->db_metadata); - mysql_mutex_unlock(&thd->LOCK_db_metadata); - try { - read_json(is, db_metadata_root); - } catch (std::exception& e) { - // NO_LINT_DEBUG - sql_print_error("Exception while reading meta data: %s, JSON: %s", - e.what(), thd->db_metadata.c_str()); - DBUG_VOID_RETURN; - } - for (auto node : db_metadata_root) - { - if (!meta_data_root.get_child_optional(node.first)) - meta_data_root.add_child(node.first, node.second); - } - } - - DBUG_VOID_RETURN; -} - /** This function finalizes the cache preparing for commit or rollback. @@ -8386,6 +8264,127 @@ static int binlog_start_trans_and_stmt(THD *thd, Log_event *start_event) DBUG_RETURN(0); } +/** + This function generated meta data in JSON format as a comment in a rows query + event. + + @see binlog_trx_meta_data + + @return JSON if all good, null string otherwise +*/ +std::string THD::gen_trx_metadata() +{ + DBUG_ENTER("THD::gen_trx_metadata"); + DBUG_ASSERT(opt_binlog_trx_meta_data); + + ptree pt; + std::ostringstream buf; + + // case: read existing meta data received from the master + if (rli_slave && !rli_slave->trx_meta_data_json.empty()) + { + std::istringstream is(rli_slave->trx_meta_data_json); + try { + read_json(is, pt); + } catch (std::exception& e) { + // NO_LINT_DEBUG + sql_print_error("Exception while reading meta data: %s, JSON: %s", + e.what(), rli_slave->trx_meta_data_json.c_str()); + DBUG_RETURN(""); + } + // clear existing data + rli_slave->trx_meta_data_json.clear(); + } + + // add things to the meta data + try { + add_time_metadata(pt); + add_db_metadata(pt); + } catch (std::exception& e) { + // NO_LINT_DEBUG + sql_print_error("Exception while adding meta data: %s", e.what()); + DBUG_RETURN(""); + } + + // write meta data with new stuff in the binlog + try { + write_json(buf, pt, false); + } catch (std::exception& e) { + // NO_LINT_DEBUG + sql_print_error("Exception while writing meta data: %s", e.what()); + DBUG_RETURN(""); + } + std::string json = buf.str(); + boost::trim(json); + + std::string comment_str= std::string("/*") + .append(TRX_META_DATA_HEADER) + .append(json) + .append("*/"); + + DBUG_RETURN(comment_str); +} + +/** + This function adds timing information in meta data JSON of rows query event. + + @see THD::write_trx_metadata + + @param meta_data_root Property tree object which represents the JSON +*/ +void THD::add_time_metadata(ptree &meta_data_root) +{ + DBUG_ENTER("THD::add_time_metadata"); + DBUG_ASSERT(opt_binlog_trx_meta_data); + + // get existing timestamps + ptree timestamps= meta_data_root.get_child("ts", ptree()); + + // add our timestamp to the array + ptree timestamp; + ulonglong millis= + std::chrono::duration_cast + (std::chrono::system_clock::now().time_since_epoch()).count(); + timestamp.put("", millis); + timestamps.push_back(std::make_pair("", timestamp)); + + // update timestamps in root + meta_data_root.erase("ts"); + meta_data_root.add_child("ts", timestamps); + + DBUG_VOID_RETURN; +} + +void THD::add_db_metadata(ptree &meta_data_root) +{ + DBUG_ENTER("THD::add_db_meta_data"); + DBUG_ASSERT(opt_binlog_trx_meta_data); + + if (!db_metadata.empty()) + { + ptree db_metadata_root; + mysql_mutex_lock(&LOCK_db_metadata); + std::istringstream is(db_metadata); + mysql_mutex_unlock(&LOCK_db_metadata); + try { + read_json(is, db_metadata_root); + } catch (std::exception& e) { + // NO_LINT_DEBUG + sql_print_error("Exception while reading meta data: %s, JSON: %s", + e.what(), db_metadata.c_str()); + DBUG_VOID_RETURN; + } + // flatten DB metadata into trx metadata + for (auto& node : db_metadata_root) + { + if (!meta_data_root.get_child_optional(node.first)) + meta_data_root.add_child(node.first, node.second); + } + } + + DBUG_VOID_RETURN; +} + /** This function writes a table map to the binary log. Note that in order to keep the signature uniform with related methods, @@ -8431,17 +8430,20 @@ int THD::binlog_write_table_map(TABLE *table, bool is_transactional, bool write_rows_query= binlog_rows_query && this->query(); if (write_rows_query) { + std::string query; + if (opt_binlog_trx_meta_data) + query.append(gen_trx_metadata()); + query.append(this->query()); + /* Write the Rows_query_log_event into binlog before the table map */ - Rows_query_log_event - rows_query_ev(this, this->query(), this->query_length()); - if ((error= cache_data->write_event(this, &rows_query_ev, - opt_binlog_trx_meta_data))) + Rows_query_log_event rows_query_ev(this, query.c_str(), query.length()); + if ((error= cache_data->write_event(this, &rows_query_ev))) DBUG_RETURN(error); } if ((error= cache_data->write_event(this, &the_event, // write meta data only if not written - // before rows query event + // before in rows query event !write_rows_query && opt_binlog_trx_meta_data))) DBUG_RETURN(error); diff --git a/sql/log_event.cc b/sql/log_event.cc index 6c75fb9983b6..1e9989c80e50 100644 --- a/sql/log_event.cc +++ b/sql/log_event.cc @@ -5295,6 +5295,15 @@ int Query_log_event::do_apply_event(Relay_log_info const *rli, int expected_error,actual_error= 0; HA_CREATE_INFO db_options; + // case: a rows query event containing trx metadata was encountered, we're + // going to clean that up here + if (rli->rows_query_ev && opt_binlog_trx_meta_data) + { + delete const_cast(rli)->rows_query_ev; + const_cast(rli)->rows_query_ev= NULL; + thd->set_query(NULL, 0); + } + /* Colleagues: please never free(thd->catalog) in MySQL. This would lead to bugs as here thd->catalog is a part of an alloced block, @@ -15087,7 +15096,7 @@ Rows_query_log_event::get_comment_length(const char* str, uint length) const { pos += 2; break; } - return comment_length ? comment_length : length; + return comment_length; } while (pos < end) { // We only get here if the first loop found the start of a comment. @@ -15102,9 +15111,10 @@ Rows_query_log_event::get_comment_length(const char* str, uint length) const { } } } - return comment_length ? comment_length : length; + return comment_length; } +#ifdef MYSQL_SERVER bool Rows_query_log_event::write_data_body(IO_CACHE *file) { @@ -15116,6 +15126,7 @@ Rows_query_log_event::write_data_body(IO_CACHE *file) DBUG_RETURN(write_str_at_most_255_bytes(file, m_rows_query, (uint) strlen(m_rows_query))); } +#endif inline ulonglong Rows_query_log_event::extract_last_timestamp() const { @@ -15148,11 +15159,16 @@ int Rows_query_log_event::do_apply_event(Relay_log_info const *rli) { const_cast(rli)->trx_meta_data_json= extract_trx_meta_data(); - DBUG_RETURN(0); + DBUG_ASSERT(strstr(m_rows_query, "*/") != NULL); + // actual query starts after the metadata + auto after_metadata= strstr(m_rows_query, "*/") + 2; + thd->set_query(after_metadata, (uint32) strlen(after_metadata)); + } + else + { + /* Set query for writing Rows_query log event into binlog later.*/ + thd->set_query(m_rows_query, (uint32) strlen(m_rows_query)); } - - /* Set query for writing Rows_query log event into binlog later.*/ - thd->set_query(m_rows_query, (uint32) strlen(m_rows_query)); DBUG_ASSERT(rli->rows_query_ev == NULL); diff --git a/sql/log_event.h b/sql/log_event.h index 9dced40bc09f..cf606f982498 100644 --- a/sql/log_event.h +++ b/sql/log_event.h @@ -5104,7 +5104,18 @@ class Rows_query_log_event : public Ignorable_log_event { #ifdef MYSQL_CLIENT virtual void print(FILE *file, PRINT_EVENT_INFO *print_event_info); #endif + +#ifdef MYSQL_SERVER + virtual bool write(IO_CACHE *file) override + { + // case: nothing to write + if (!*m_rows_query) + return 0; + return Log_event::write(file); + } + virtual bool write_data_body(IO_CACHE *file); +#endif virtual Log_event_type get_type_code() { return ROWS_QUERY_LOG_EVENT; } @@ -5115,10 +5126,13 @@ class Rows_query_log_event : public Ignorable_log_event { bool has_trx_meta_data() const { + std::string str(m_rows_query); + if (str.length() < (2 + TRX_META_DATA_HEADER.length() + 2)) + return false; // NOTE: Meta data comment format: /*::TRX_META_DATA::{.. JSON ..}*/ // so to check if the event contains trx meta data we check if the string // "::TRX_META_DATA::" is present after the first two "/*" characters. - return std::string(m_rows_query) + return str .compare(2, TRX_META_DATA_HEADER.length(), TRX_META_DATA_HEADER) == 0; } diff --git a/sql/rpl_slave.cc b/sql/rpl_slave.cc index 9431278340b1..0aa0ce686fd1 100644 --- a/sql/rpl_slave.cc +++ b/sql/rpl_slave.cc @@ -4764,11 +4764,10 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli) used to read info about the relay log's format; it will be deleted when the SQL thread does not need it, i.e. when this thread terminates. ROWS_QUERY_LOG_EVENT is destroyed at the end of the current statement - clean-up routine but ones with trx meta data are deleted here. + clean-up routine. */ if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT && - !(ev->get_type_code() == ROWS_QUERY_LOG_EVENT && - !((Rows_query_log_event*) ev)->has_trx_meta_data())) + ev->get_type_code() != ROWS_QUERY_LOG_EVENT) { DBUG_PRINT("info", ("Deleting the event after it has been executed")); delete ev; diff --git a/sql/sql_binlog.cc b/sql/sql_binlog.cc index 8a7ca4da14fe..43eb75d59847 100644 --- a/sql/sql_binlog.cc +++ b/sql/sql_binlog.cc @@ -292,11 +292,10 @@ void mysql_client_binlog_statement(THD* thd) will be deleted when the SQL thread does not need it, i.e. when this thread terminates. ROWS_QUERY_LOG_EVENT if present in rli is deleted at the end - of the event but ones with trx meta data are deleted here. + of the event. */ if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT && - !(ev->get_type_code() == ROWS_QUERY_LOG_EVENT && - !((Rows_query_log_event*) ev)->has_trx_meta_data())) + ev->get_type_code() != ROWS_QUERY_LOG_EVENT) { delete ev; ev= NULL; diff --git a/sql/sql_class.h b/sql/sql_class.h index a0d034a1a4b6..6bc301ec00cb 100644 --- a/sql/sql_class.h +++ b/sql/sql_class.h @@ -56,6 +56,9 @@ #include "my_atomic.h" #include "sql_db.h" +#include +using boost::property_tree::ptree; + #define FLAGSTR(V,F) ((V)&(F)?#F" ":"") /** @@ -2656,6 +2659,10 @@ class THD :public MDL_context_owner, const uchar* extra_row_info); void binlog_prepare_row_images(TABLE* table, bool is_update); + std::string gen_trx_metadata(); + void add_time_metadata(ptree &meta_data_root); + void add_db_metadata(ptree &meta_data_root); + void set_server_id(uint32 sid) { server_id = sid; } /*