2010-10-15 19:04, Sven Sandberg wrote:
> Hi Daogang,
>
> Thanks for your work! I think this is a good patch, but we can make it
> even better as follows:
>
> (1) Get rid of the head cache and write the head for every event.
> (2) Print a warning if the body cache is nonempty after a binlog has
> been processed.
Thanks for the comments. Please review the updated patch:
http://lists.mysql.com/commits/121066
I didn't test the case of multi rows events in one statement,
the headers of other rows events also will be displayed if
the last rows event is discarded by slave I/O thread in the
patch. Because the case caused bug #57548. The case will
be tested in the patch of bug #57548 by the way.
Best Regards,
Daogang
>
> ==== Background ====
>
> mysqlbinlog outputs every event in two parts: the head (typically a
> comment starting with #) and the body (typically an SQL statement).
> Normally, mysqlbinlog writes first the head and then the body directly
> to the output, for each event. However, when it sees a row event or a
> table_map event, it writes the head to a special IO_CACHE, and it
> writes the body to another IO_CACHE. When it sees a an event with
> STMT_END_F set, it flushes first the head cache and then the body
> cache. So all heads that originate from the same SQL statement are
> grouped together, then all bodies are grouped together. The reason is
> that all bodies should be grouped together so that they make up one
> BINLOG statement.
>
> ==== Problem ====
>
> The reason for the bug was that the IO thread was interrupted when it
> had written some but not all events for a statement. So it never saw
> the STMT_END_F, so it never flushed the caches.
>
> ==== Fix ====
>
> Your fix flushes the head cache for each Table_map event. I think this
> is good, but it does not solve all problems. If there are two row
> events, and the IO thread stops after the first row event, then
> mysqlbinlog will still not show anything for the first row event.
>
> So I think it should also flush the head cache for each row event. But
> actually, if we do that, we can as well write the head directly to the
> output. There is no need to cache it.
>
> I think it is good that you don't flush the body cache when no
> STMT_END_F is seen, because it would produce a BINLOG statement with
> rows from a half statement. It could be dangerous to execute that.
> However, I think it would be good to print a warning, and perhaps to
> print the BINLOG statement commented out so that users have the option
> to use it or not.
>
> /Sven
>
>
> On 10/14/2010 09:46 AM, Dao-Gang.Qu@stripped wrote:
>> #At
>> file:///home/daogangqu/mysql/bzrwork1/bug55790/mysql-next-mr-bugfixing/
>> based on revid:dao-gang.qu@stripped
>>
>> 3324 Dao-Gang.Qu@stripped 2010-10-14
>> Bug #55790 Read_Master_Log_Pos is wrong after
>> Slave_IO_Error= ER_NET_PACKET_TOO_LARGE
>>
>> When logging in row format, DML is written as a Table_map_event
>> followed by its row events. The Table_map_event is written to
>> the relay log by slave I/O thread even if its rows events are
>> discarded. But it is not displayed by MYSQLBINLOG and
>> SHOW RELAYLOG EVENTS. However, the Read_Master_Log_Pos displayed
>> by SHOW SLAVE STATUS is at the end of the Table_map_Log_event.
>>
>> After the patch, the Table_map_log_event will be displayed by
>> MYSQLBINLOG and SHOW RELAYLOG EVENTS so long as it is written
>> to the relay log, even if its rows events are discarded;
>> @ mysql-test/suite/rpl/r/rpl_packet.result
>> Test result for Bug #55790
>> @ mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
>> Updated for the patch of Bug #55790.
>> @ mysql-test/suite/rpl/t/rpl_packet.test
>> Added test to verify if the the Table_map_log_event will
>> be displayed by MYSQLBINLOG and SHOW RELAYLOG EVENTS
>> so long as it was written to the relay log, even if
>> its rows events are discarded;
>> @ sql/log_event.cc
>> Added code to sync the Table_map_log_event to file from catch
>> directly instead of waiting for its rows event gogether.
>>
>> modified:
>> mysql-test/suite/rpl/r/rpl_packet.result
>> mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
>> mysql-test/suite/rpl/t/rpl_packet.test
>> sql/log_event.cc
>> === modified file 'mysql-test/suite/rpl/r/rpl_packet.result'
>> --- a/mysql-test/suite/rpl/r/rpl_packet.result 2010-07-20 15:27:13
>> +0000
>> +++ b/mysql-test/suite/rpl/r/rpl_packet.result 2010-10-14 07:46:50
>> +0000
>> @@ -57,6 +57,39 @@ SHOW BINLOG EVENTS;
>> SET @max_allowed_packet_1= @@session.max_allowed_packet;
>> SHOW BINLOG EVENTS;
>> SET @max_allowed_packet_2= @@session.max_allowed_packet;
>> +START SLAVE;
>> +DROP TABLE t1;
>> +select @@global.max_allowed_packet;
>> +@@global.max_allowed_packet
>> +4096
>> +select @@global.net_buffer_length;
>> +@@global.net_buffer_length
>> +4096
>> +select @@global.max_allowed_packet;
>> +@@global.max_allowed_packet
>> +1024
>> +select @@global.net_buffer_length;
>> +@@global.net_buffer_length
>> +1024
>> +CREATE TABLE t1 (a TEXT) ENGINE=MyISAM;
>> +INSERT INTO t1 VALUES (REPEAT('a', 2048));
>> +call mtr.add_suppression("Slave I/O: Got a packet bigger than
>> 'max_allowed_packet' bytes, Error_code: 1153");
>> +# 1153 = ER_NET_PACKET_TOO_LARGE
>> +Last_IO_Error = Got a packet bigger than 'max_allowed_packet' bytes
>> +# Now Read_Master_Log_Pos is as following:
>> +Read_Master_Log_Pos 424
>> +# Test the Table_map_log_event is dispalyed at Read_Master_Log_Pos
>> by MYSQLBINLOG
>> +Last event in relay log:
>> +#server id # end_log_pos 424 Table_map: `test`.`t1` mapped to
>> number #
>> +# Test the Table_map_log_event is displayed at end by SHOW RELAYLOG
>> EVENTS
>> +show relaylog events in 'slave-relay-bin.000003' from<binlog_start>;
>> +Log_name Pos Event_type Server_id End_log_pos Info
>> +slave-relay-bin.000003 # Rotate # #
>> master-bin.000001;pos=4
>> +slave-relay-bin.000003 # Format_desc # #
>> SERVER_VERSION, BINLOG_VERSION
>> +slave-relay-bin.000003 # Query # # use `test`; DROP
>> TABLE `t1` /* generated by server */
>> +slave-relay-bin.000003 # Query # # use `test`; CREATE
>> TABLE t1 (a TEXT) ENGINE=MyISAM
>> +slave-relay-bin.000003 # Query # # BEGIN
>> +slave-relay-bin.000003 # Table_map # # table_id: #
>> (test.t1)
>> ==== clean up ====
>> DROP TABLE t1;
>> SET @@global.max_allowed_packet= 1024;
>>
>> === modified file
>> 'mysql-test/suite/rpl/r/rpl_row_ignorable_event.result'
>> --- a/mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
>> 2010-09-01 02:51:08 +0000
>> +++ b/mysql-test/suite/rpl/r/rpl_row_ignorable_event.result
>> 2010-10-14 07:46:50 +0000
>> @@ -173,8 +173,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t1(a,b) values(1,1),(2,1)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t1` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t1
>> ### SET
>> @@ -198,8 +198,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # update t1 set a = a + 5 where b = 1 LIMIT 1
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t1` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Update_rows: table id # flags:
>> STMT_END_F
>> ### UPDATE test.t1
>> ### WHERE
>> @@ -222,8 +222,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # delete from t1 where a = 6
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t1` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Delete_rows: table id # flags:
>> STMT_END_F
>> ### DELETE FROM test.t1
>> ### WHERE
>> @@ -248,8 +248,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t2(a,b) values(2,1),(3,1)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t2` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t2
>> ### SET
>> @@ -263,8 +263,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # update t2 set a = a + 5 where b = 1
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t2` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Update_rows: table id # flags:
>> STMT_END_F
>> ### UPDATE test.t2
>> ### WHERE
>> @@ -284,8 +284,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # delete from t2 where a = 7
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t2` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Delete_rows: table id # flags:
>> STMT_END_F
>> ### DELETE FROM test.t2
>> ### WHERE
>> @@ -303,8 +303,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t1(a,b) values(1,5)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t1` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t1
>> ### SET
>> @@ -324,8 +324,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t1(a,b) values(1,7)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t1` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t1
>> ### SET
>> @@ -345,8 +345,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t2(a,b) values(2,5)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t2` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t2
>> ### SET
>> @@ -356,8 +356,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t2(a,b) values(2,6)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t2` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t2
>> ### SET
>> @@ -395,8 +395,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t3(a, b) values(1,1)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t3` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t3
>> ### SET
>> @@ -416,8 +416,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t4(a, b) values(2,1)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t4` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t4
>> ### SET
>> @@ -437,11 +437,11 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # update t3,t4 set t3.a=3, t4.a=4 where t3.b=t4.b
>> # at #
>> +#server id # end_log_pos # Table_map: `test`.`t3` mapped to
>> number #
>> # at #
>> +#server id # end_log_pos # Table_map: `test`.`t4` mapped to
>> number #
>> # at #
>> # at #
>> -#server id # end_log_pos # Table_map: `test`.`t3` mapped to
>> number #
>> -#server id # end_log_pos # Table_map: `test`.`t4` mapped to
>> number #
>> #server id # end_log_pos # Update_rows: table id #
>> #server id # end_log_pos # Update_rows: table id # flags:
>> STMT_END_F
>> ### UPDATE test.t3
>> @@ -472,8 +472,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert into t5(a, b) values(3,1)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t5` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t5
>> ### SET
>> @@ -493,10 +493,10 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # update t4,t5 set t4.a=4, t5.a=5 where t4.b=t5.b
>> # at #
>> -# at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t4` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Table_map: `test`.`t5` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Update_rows: table id # flags:
>> STMT_END_F
>> ### UPDATE test.t5
>> ### WHERE
>> @@ -519,8 +519,8 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # insert delayed into t3(a,b) values(1,5),(1,6),(1,7)
>> # at #
>> -# at #
>> #server id # end_log_pos # Table_map: `test`.`t3` mapped to
>> number #
>> +# at #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t3
>> ### SET
>> @@ -553,9 +553,9 @@ BEGIN
>> #server id # end_log_pos # Rows_query
>> # load data infile '../../std_data/words.dat' into table t6
>> # at #
>> +#server id # end_log_pos # Table_map: `test`.`t6` mapped to
>> number #
>> # at #
>> # at #
>> -#server id # end_log_pos # Table_map: `test`.`t6` mapped to
>> number #
>> #server id # end_log_pos # Write_rows: table id #
>> #server id # end_log_pos # Write_rows: table id # flags:
>> STMT_END_F
>> ### INSERT INTO test.t6
>>
>> === modified file 'mysql-test/suite/rpl/t/rpl_packet.test'
>> --- a/mysql-test/suite/rpl/t/rpl_packet.test 2010-08-06 08:54:01
>> +0000
>> +++ b/mysql-test/suite/rpl/t/rpl_packet.test 2010-10-14 07:46:50
>> +0000
>> @@ -152,6 +152,56 @@ if (`SELECT NOT(@max_allowed_packet_0 =
>> --die @max_allowed_packet changed after executing SHOW BINLOG EVENTS
>> }
>>
>> +#
>> +# BUG#55790
>> +# This test verifies if the the Table_map_log_event will
>> +# be displayed by MYSQLBINLOG and SHOW RELAYLOG EVENTS
>> +# so long as it was written to the relay log, even if
>> +# its rows events are discarded;
>> +#
>> +
>> +connection slave;
>> +START SLAVE;
>> +--source include/wait_for_slave_to_start.inc
>> +connection master;
>> +DROP TABLE t1;
>> +select @@global.max_allowed_packet;
>> +select @@global.net_buffer_length;
>> +sync_slave_with_master;
>> +select @@global.max_allowed_packet;
>> +select @@global.net_buffer_length;
>> +
>> +--connection master
>> +CREATE TABLE t1 (a TEXT) ENGINE=MyISAM;
>> +--sync_slave_with_master
>> +
>> +# Create big row event.
>> +--connection master
>> +INSERT INTO t1 VALUES (REPEAT('a', 2048));
>> +
>> +# Slave IO thread should stop with error when trying to read the big
>> event.
>> +--connection slave
>> +call mtr.add_suppression("Slave I/O: Got a packet bigger than
>> 'max_allowed_packet' bytes, Error_code: 1153");
>> +--echo # 1153 = ER_NET_PACKET_TOO_LARGE
>> +--let $slave_io_errno= 1153
>> +--let $show_slave_io_error= 1
>> +--source include/wait_for_slave_io_error.inc
>> +
>> +--echo # Now Read_Master_Log_Pos is as following:
>> +--let $status_items= Read_Master_Log_Pos
>> +--source include/show_slave_status.inc
>> +
>> +--echo # Test the Table_map_log_event is dispalyed at
>> Read_Master_Log_Pos by MYSQLBINLOG
>> +--let $MYSQLD_DATADIR= `SELECT @@datadir`
>> +--echo Last event in relay log:
>> +--let $binlog_file= query_get_value(SHOW SLAVE STATUS,
>> Relay_Log_File, 1)
>> +--replace_regex /#[0-9]*[ ]*[0-9]*:[0-9]*:[0-9]* server id
>> [0-9]*/#server id #/ /mapped to number [0-9]*/mapped to number #/
>> +exec $MYSQL_BINLOG $MYSQLD_DATADIR/$binlog_file
>> + | grep 'end_log_pos'
>> + | tail -n 1;
>> +
>> +--echo # Test the Table_map_log_event is displayed at end by SHOW
>> RELAYLOG EVENTS
>> +--source include/show_relaylog_events.inc
>>
>> --echo ==== clean up ====
>> connection master;
>>
>> === modified file 'sql/log_event.cc'
>> --- a/sql/log_event.cc 2010-09-24 15:24:54 +0000
>> +++ b/sql/log_event.cc 2010-10-14 07:46:50 +0000
>> @@ -8552,6 +8552,7 @@ void Table_map_log_event::print(FILE *fi
>> "\tTable_map: `%s`.`%s` mapped to number %lu\n",
>> m_dbnam, m_tblnam, m_table_id);
>> print_base64(&print_event_info->body_cache, print_event_info,
>> TRUE);
>> +
>> copy_event_cache_to_file_and_reinit(&print_event_info->head_cache,
>> file);
>> }
>> }
>> #endif
>>
>>
>>
>>
>>
>
