List:Commits« Previous MessageNext Message »
From:Daogang Qu Date:October 18 2010 7:26am
Subject:Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)
Bug#55790
View as plain text  
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
>>
>>
>>
>>
>>
>

Thread
bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324) Bug#55790Dao-Gang.Qu14 Oct
  • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Sven Sandberg15 Oct
    • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Daogang Qu18 Oct
    • Re: bzr commit into mysql-next-mr-bugfixing branch (Dao-Gang.Qu:3324)Bug#55790Daogang Qu19 Oct