2010-10-15 19:04, Sven Sandberg wrote:
> Hi Li-Bing,
>
> 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.
Seems we didn't have a fun for writing the head directly to the output.
> (2) Print a warning if the body cache is nonempty after a binlog has
> been processed.
I didn't get the idea. Why print a warning. It would not produce a
BINLOG statement with rows
from a half statement, even if MYSQLBINLOG will display the header of
the first rows event in
the case of there are two row events, and the IO thread stops after the
first row event.
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
>>
>>
>>
>>
>>
>
