List:Commits« Previous MessageNext Message »
From:Daogang Qu Date:October 19 2010 9:08am
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 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
>>
>>
>>
>>
>>
>


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