From 25af844f6feda6ec9cfb094b4ca4f49aac7d3ecc Mon Sep 17 00:00:00 2001 From: "tnurnberg@sin.intern.azundris.com" <> Date: Mon, 25 Jun 2007 11:34:23 +0200 Subject: [PATCH 1/4] Bug #22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB fix binlog-writing so that end_log_pos is given correctly even within transactions for both SHOW BINLOG and SHOW MASTER STATUS, that is as absolute values (from log start) rather than relative values (from transaction's start). --- Merge tnurnberg@bk-internal.mysql.com:/home/bk/mysql-5.0-maint into sin.intern.azundris.com:/home/tnurnberg/22540/50-22540 --- mysql-test/r/binlog.result | 122 ++++++++++++++++++++++++++++++++++++- mysql-test/t/binlog.test | 93 +++++++++++++++++++++++++++- sql/log.cc | 63 +++++++++++++++++-- 3 files changed, 269 insertions(+), 9 deletions(-) diff --git a/mysql-test/r/binlog.result b/mysql-test/r/binlog.result index 6807da16e66..41c75a2067b 100644 --- a/mysql-test/r/binlog.result +++ b/mysql-test/r/binlog.result @@ -1,6 +1,6 @@ drop table if exists t1, t2; reset master; -create table t1 (a int) engine=bdb; +create table t1 (a int) engine=innodb; create table t2 (a int) engine=innodb; begin; insert t1 values (5); @@ -10,11 +10,11 @@ insert t2 values (5); commit; show binlog events from 98; Log_name Pos Event_type Server_id End_log_pos Info -master-bin.000001 # Query 1 # use `test`; create table t1 (a int) engine=bdb +master-bin.000001 # Query 1 # use `test`; create table t1 (a int) engine=innodb master-bin.000001 # Query 1 # use `test`; create table t2 (a int) engine=innodb master-bin.000001 # Query 1 # use `test`; BEGIN master-bin.000001 # Query 1 # use `test`; insert t1 values (5) -master-bin.000001 # Query 1 # use `test`; COMMIT +master-bin.000001 # Xid 1 # COMMIT /* XID */ master-bin.000001 # Query 1 # use `test`; BEGIN master-bin.000001 # Query 1 # use `test`; insert t2 values (5) master-bin.000001 # Xid 1 # COMMIT /* XID */ @@ -133,3 +133,119 @@ master-bin.000001 # Rotate 1 # master-bin.000002;pos=4 show binlog events in 'master-bin.000002' from 98; Log_name Pos Event_type Server_id End_log_pos Info master-bin.000002 # Query 1 # use `test`; drop table t1 +set @ac = @@autocommit; +set autocommit= 0; +reset master; +create table t1(n int) engine=innodb; +begin; +insert into t1 values (1); +insert into t1 values (2); +insert into t1 values (3); +commit; +drop table t1; +show binlog events from 0; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 98 Server version, Binlog ver: 4 +master-bin.000001 98 Query 1 197 use `test`; create table t1(n int) engine=innodb +master-bin.000001 197 Query 1 265 use `test`; BEGIN +master-bin.000001 265 Query 1 353 use `test`; insert into t1 values (1) +master-bin.000001 353 Query 1 441 use `test`; insert into t1 values (2) +master-bin.000001 441 Query 1 529 use `test`; insert into t1 values (3) +master-bin.000001 529 Xid 1 556 COMMIT /* XID */ +master-bin.000001 556 Query 1 632 use `test`; drop table t1 +set autocommit= 1; +reset master; +create table t1(n int) engine=innodb; +insert into t1 values (1); +insert into t1 values (2); +insert into t1 values (3); +commit; +drop table t1; +show binlog events from 0; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 98 Server version, Binlog ver: 4 +master-bin.000001 98 Query 1 197 use `test`; create table t1(n int) engine=innodb +master-bin.000001 197 Query 1 285 use `test`; insert into t1 values (1) +master-bin.000001 285 Xid 1 312 COMMIT /* XID */ +master-bin.000001 312 Query 1 400 use `test`; insert into t1 values (2) +master-bin.000001 400 Xid 1 427 COMMIT /* XID */ +master-bin.000001 427 Query 1 515 use `test`; insert into t1 values (3) +master-bin.000001 515 Xid 1 542 COMMIT /* XID */ +master-bin.000001 542 Query 1 618 use `test`; drop table t1 +reset master; +create table t1(n int) engine=myisam; +begin; +insert into t1 values (4); +insert into t1 values (5); +insert into t1 values (6); +commit; +drop table t1; +show binlog events from 0; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 98 Server version, Binlog ver: 4 +master-bin.000001 98 Query 1 197 use `test`; create table t1(n int) engine=myisam +master-bin.000001 197 Query 1 285 use `test`; insert into t1 values (4) +master-bin.000001 285 Query 1 373 use `test`; insert into t1 values (5) +master-bin.000001 373 Query 1 461 use `test`; insert into t1 values (6) +master-bin.000001 461 Query 1 537 use `test`; drop table t1 +set autocommit= 1; +reset master; +create table t1(n int) engine=innodb; +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 197 +insert into t1 values (1); +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 312 +insert into t1 values (2); +insert into t1 values (3); +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 542 +commit; +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 542 +drop table t1; +show binlog events from 0; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 98 Server version, Binlog ver: 4 +master-bin.000001 98 Query 1 197 use `test`; create table t1(n int) engine=innodb +master-bin.000001 197 Query 1 285 use `test`; insert into t1 values (1) +master-bin.000001 285 Xid 1 312 COMMIT /* XID */ +master-bin.000001 312 Query 1 400 use `test`; insert into t1 values (2) +master-bin.000001 400 Xid 1 427 COMMIT /* XID */ +master-bin.000001 427 Query 1 515 use `test`; insert into t1 values (3) +master-bin.000001 515 Xid 1 542 COMMIT /* XID */ +master-bin.000001 542 Query 1 618 use `test`; drop table t1 +set autocommit= 0; +reset master; +create table t1(n int) engine=myisam; +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 197 +insert into t1 values (4); +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 285 +insert into t1 values (5); +insert into t1 values (6); +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 461 +commit; +show master status; +File Position Binlog_Do_DB Binlog_Ignore_DB +master-bin.000001 461 +drop table t1; +show binlog events from 0; +Log_name Pos Event_type Server_id End_log_pos Info +master-bin.000001 4 Format_desc 1 98 Server version, Binlog ver: 4 +master-bin.000001 98 Query 1 197 use `test`; create table t1(n int) engine=myisam +master-bin.000001 197 Query 1 285 use `test`; insert into t1 values (4) +master-bin.000001 285 Query 1 373 use `test`; insert into t1 values (5) +master-bin.000001 373 Query 1 461 use `test`; insert into t1 values (6) +master-bin.000001 461 Query 1 537 use `test`; drop table t1 +set session autocommit = @ac; +End of 5.0 tests diff --git a/mysql-test/t/binlog.test b/mysql-test/t/binlog.test index accfa6a577f..6271a8f95a8 100644 --- a/mysql-test/t/binlog.test +++ b/mysql-test/t/binlog.test @@ -3,7 +3,6 @@ # -- source include/have_log_bin.inc -- source include/not_embedded.inc --- source include/have_bdb.inc -- source include/have_innodb.inc -- source include/have_log_bin.inc @@ -12,7 +11,7 @@ drop table if exists t1, t2; --enable_warnings reset master; -create table t1 (a int) engine=bdb; +create table t1 (a int) engine=innodb; create table t2 (a int) engine=innodb; begin; insert t1 values (5); @@ -49,3 +48,93 @@ show binlog events in 'master-bin.000001' from 98; --replace_column 2 # 5 # show binlog events in 'master-bin.000002' from 98; +# +# Bug#22540 - Incorrect value in column End_log_pos of +# SHOW BINLOG EVENTS using InnoDB +# + +# the following tests will show that certain queries now return +# absolute offsets (from binlog start, rather than relative to +# the beginning of the current transaction). under what +# conditions it should be allowed / is sensible to put the +# slider into the middle of a transaction is not our concern +# here; we just guarantee that if and when it's done, the +# user has valid offsets to use. if the setter function still +# wants to throw a "positioning into middle of transaction" +# warning, that's its prerogative and handled elsewhere. + +set @ac = @@autocommit; + +# first show this to work for SHOW BINLOG EVENTS + +set autocommit= 0; +reset master; +create table t1(n int) engine=innodb; +begin; +insert into t1 values (1); +insert into t1 values (2); +insert into t1 values (3); +commit; +drop table t1; +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /table_id: [0-9]+/table_id: #/ /Server ver: [^,]*,/Server version,/ +show binlog events from 0; + +set autocommit= 1; +reset master; +create table t1(n int) engine=innodb; +insert into t1 values (1); +insert into t1 values (2); +insert into t1 values (3); +commit; +drop table t1; +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /table_id: [0-9]+/table_id: #/ /Server ver: [^,]*,/Server version,/ +show binlog events from 0; + +reset master; +create table t1(n int) engine=myisam; +begin; +insert into t1 values (4); +insert into t1 values (5); +insert into t1 values (6); +commit; +drop table t1; +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /table_id: [0-9]+/table_id: #/ /Server ver: [^,]*,/Server version,/ +show binlog events from 0; + +# now show this also works for SHOW MASTER STATUS +# as this is what "mysqldump --master-data=1" uses. + +set autocommit= 1; +reset master; +create table t1(n int) engine=innodb; +show master status; +insert into t1 values (1); +show master status; +insert into t1 values (2); +insert into t1 values (3); +show master status; +commit; +show master status; +drop table t1; +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /table_id: [0-9]+/table_id: #/ /Server ver: [^,]*,/Server version,/ +show binlog events from 0; + +set autocommit= 0; +reset master; +create table t1(n int) engine=myisam; +show master status; +insert into t1 values (4); +show master status; +insert into t1 values (5); +insert into t1 values (6); + +show master status; +commit; +show master status; +drop table t1; +--replace_regex /\/\* xid=.* \*\//\/* XID *\// /table_id: [0-9]+/table_id: #/ /Server ver: [^,]*,/Server version,/ +show binlog events from 0; + +set session autocommit = @ac; + +--echo End of 5.0 tests diff --git a/sql/log.cc b/sql/log.cc index 818828f9557..465d694ba10 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -134,7 +134,7 @@ static int binlog_commit(THD *thd, bool all) // we're here because trans_log was flushed in MYSQL_LOG::log_xid() DBUG_RETURN(0); } - if (all) + if (all) { Query_log_event qev(thd, STRING_WITH_LEN("COMMIT"), TRUE, FALSE); qev.error_code= 0; // see comment in MYSQL_LOG::write(THD, IO_CACHE) @@ -1835,7 +1835,9 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event) if (likely(is_open())) // Should always be true { - uint length; + uint length, group, carry, hdr_offs; + long val; + byte header[LOG_EVENT_HEADER_LEN]; /* Log "BEGIN" at the beginning of the transaction. @@ -1867,13 +1869,66 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event) /* Read from the file used to cache the queries .*/ if (reinit_io_cache(cache, READ_CACHE, 0, 0, 0)) goto err; - length=my_b_bytes_in_cache(cache); + + length= my_b_bytes_in_cache(cache); DBUG_EXECUTE_IF("half_binlogged_transaction", length-=100;); + + group= my_b_tell(&log_file); + hdr_offs= carry= 0; + do { + if (likely(carry > 0)) + { + DBUG_ASSERT(carry < LOG_EVENT_HEADER_LEN); + + memcpy(&header[carry], (char *)cache->read_pos, LOG_EVENT_HEADER_LEN - carry); + + val= uint4korr(&header[LOG_POS_OFFSET]) + group; + int4store(&header[LOG_POS_OFFSET], val); + + if (my_b_write(&log_file, header, carry)) + goto err; + + memcpy((char *)cache->read_pos, &header[carry], LOG_EVENT_HEADER_LEN - carry); + + hdr_offs = LOG_EVENT_HEADER_LEN - carry + + uint4korr(&header[EVENT_LEN_OFFSET]); + + carry= 0; + } + + if(likely(length > 0)) + { + do { + DBUG_ASSERT((hdr_offs + max(EVENT_LEN_OFFSET, LOG_POS_OFFSET) + 4) <= length); + + val= uint4korr((char *)cache->read_pos + hdr_offs + LOG_POS_OFFSET) + group; + int4store((char *)cache->read_pos + hdr_offs + LOG_POS_OFFSET, val); + hdr_offs += uint4korr((char *)cache->read_pos + hdr_offs + EVENT_LEN_OFFSET); + + /* header beyond current read-buffer? */ + if (hdr_offs >= length) + { + hdr_offs -= length; + break; + } + + /* split header? */ + if (hdr_offs + LOG_EVENT_HEADER_LEN > length) + { + carry= length - hdr_offs; + + memcpy(header, (char *)cache->read_pos + hdr_offs, carry); + length -= carry; + } + + } while (hdr_offs < length); + } + /* Write data to the binary log file */ if (my_b_write(&log_file, cache->read_pos, length)) - goto err; + goto err; cache->read_pos=cache->read_end; // Mark buffer used up DBUG_EXECUTE_IF("half_binlogged_transaction", goto DBUG_skip_commit;); } while ((length=my_b_fill(cache))); From 874ccf025dcd9df0d6962306e810f299a49e9901 Mon Sep 17 00:00:00 2001 From: "tnurnberg@sin.intern.azundris.com" <> Date: Mon, 25 Jun 2007 18:41:17 +0200 Subject: [PATCH 2/4] Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB end_log_pos data within a transaction are relative to the start of the transaction rather than absolute. we fix those groups in situ before writing the log out. additional comments and handling for groups with very large single events, as suggested by Guilhem. --- sql/log.cc | 90 +++++++++++++++++++++++++++++++++++++++++------------- 1 file changed, 68 insertions(+), 22 deletions(-) diff --git a/sql/log.cc b/sql/log.cc index 465d694ba10..a5c5f42a393 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -1835,8 +1835,7 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event) if (likely(is_open())) // Should always be true { - uint length, group, carry, hdr_offs; - long val; + uint length, group, carry, hdr_offs, val; byte header[LOG_EVENT_HEADER_LEN]; /* @@ -1873,57 +1872,104 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event) length= my_b_bytes_in_cache(cache); DBUG_EXECUTE_IF("half_binlogged_transaction", length-=100;); + /* + The events in the buffer have incorrect end_log_pos data + (relative to beginning of group rather than absolute), + so we'll recalculate them in situ so the binlog is always + correct, even in the middle of a group. This is possible + because we now know the start position of the group (the + offset of this cache in the log, if you will); all we need + to do is to find all event-headers, and add the position of + the group to the end_log_pos of each event. This is pretty + straight forward, except that we read the cache in segments, + so an event-header might end up on the cache-border and get + split. + */ + group= my_b_tell(&log_file); hdr_offs= carry= 0; do { - if (likely(carry > 0)) + + /* + if we only got a partial header in the last iteration, + get the other half now and process a full header. + */ + if (unlikely(carry > 0)) { DBUG_ASSERT(carry < LOG_EVENT_HEADER_LEN); + /* assemble both halves */ memcpy(&header[carry], (char *)cache->read_pos, LOG_EVENT_HEADER_LEN - carry); + /* fix end_log_pos */ val= uint4korr(&header[LOG_POS_OFFSET]) + group; int4store(&header[LOG_POS_OFFSET], val); + /* write the first half of the split header */ if (my_b_write(&log_file, header, carry)) goto err; + /* + copy fixed second half of header to cache so the correct + version will be written later. + */ memcpy((char *)cache->read_pos, &header[carry], LOG_EVENT_HEADER_LEN - carry); + /* next event header at ... */ hdr_offs = LOG_EVENT_HEADER_LEN - carry + uint4korr(&header[EVENT_LEN_OFFSET]); carry= 0; } + /* if there is anything to write, process it. */ + if(likely(length > 0)) { - do { - DBUG_ASSERT((hdr_offs + max(EVENT_LEN_OFFSET, LOG_POS_OFFSET) + 4) <= length); + /* + next header beyond current read-buffer? we'll get it later + (though not necessarily in the very next iteration). + */ - val= uint4korr((char *)cache->read_pos + hdr_offs + LOG_POS_OFFSET) + group; - int4store((char *)cache->read_pos + hdr_offs + LOG_POS_OFFSET, val); - hdr_offs += uint4korr((char *)cache->read_pos + hdr_offs + EVENT_LEN_OFFSET); + if (hdr_offs >= length) + hdr_offs -= length; + else + { - /* header beyond current read-buffer? */ - if (hdr_offs >= length) - { - hdr_offs -= length; - break; - } + /* process all event-headers in this (partial) cache. */ - /* split header? */ - if (hdr_offs + LOG_EVENT_HEADER_LEN > length) - { - carry= length - hdr_offs; + do { - memcpy(header, (char *)cache->read_pos + hdr_offs, carry); - length -= carry; - } + /* + partial header only? save what we can get, process once + we get the rest. + */ - } while (hdr_offs < length); + if (hdr_offs + LOG_EVENT_HEADER_LEN > length) + { + carry= length - hdr_offs; + memcpy(header, (char *)cache->read_pos + hdr_offs, carry); + length= hdr_offs; + } + else + { + /* we've got a full event-header, and it came in one piece */ + + char *log_pos= cache->read_pos + hdr_offs + LOG_POS_OFFSET; + + /* fix end_log_pos */ + val= uint4korr(log_pos) + group; + int4store(log_pos, val); + + /* next event header at ... */ + log_pos= (char *)cache->read_pos + hdr_offs + EVENT_LEN_OFFSET; + hdr_offs += uint4korr(log_pos); + + } + } while (hdr_offs < length); + } } /* Write data to the binary log file */ From 131db8123fc0054db7e46e0e5154623da2d9d537 Mon Sep 17 00:00:00 2001 From: "tnurnberg@sin.intern.azundris.com" <> Date: Wed, 27 Jun 2007 09:30:29 +0200 Subject: [PATCH 3/4] Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB windows fixies --- sql/log.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sql/log.cc b/sql/log.cc index a5c5f42a393..f682b9b206e 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -1886,7 +1886,7 @@ bool MYSQL_LOG::write(THD *thd, IO_CACHE *cache, Log_event *commit_event) split. */ - group= my_b_tell(&log_file); + group= (uint)my_b_tell(&log_file); hdr_offs= carry= 0; do From dadc4c74994d189e12782c7ef6724e2cc17ca263 Mon Sep 17 00:00:00 2001 From: "tnurnberg@sin.intern.azundris.com" <> Date: Wed, 27 Jun 2007 09:31:47 +0200 Subject: [PATCH 4/4] Bug#22540: Incorrect value in column End_log_pos of SHOW BINLOG EVENTS using InnoDB windows fixies --- sql/log.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sql/log.cc b/sql/log.cc index 831066ab401..6e635ba581c 100644 --- a/sql/log.cc +++ b/sql/log.cc @@ -3963,7 +3963,7 @@ int MYSQL_BIN_LOG::write_cache(IO_CACHE *cache, bool lock_log, bool sync_log) split. */ - group= my_b_tell(&log_file); + group= (uint)my_b_tell(&log_file); hdr_offs= carry= 0; do