List:Commits« Previous MessageNext Message »
From:Sven Sandberg Date:November 5 2010 11:23am
Subject:BUG#56790 review (2)
View as plain text  
Hi Daogang,

Thanks for this patch, it looks much better. I think there are still 
some places we can improve, so I'll reject the patch. Summary of 
suggestions (see comments inline):

  (S1) set have_unflushed_events=TRUE *before* 
copy_event_cache_to_file_and_reinit, not after.

  (S2) wrong flags passed to mysqlbinlog

  (S3) compare mysqlbinlog to a string containing 'Table_map'

  (S4) execute 'die' when test case fails

  (S5) initialize have_unflushed_events in the constructor, not in init_ok()

/Sven


> diff.patch.bug55790
>
> === modified file 'client/mysqlbinlog.cc'
> --- client/mysqlbinlog.cc	2010-11-01 05:40:27 +0000
> +++ client/mysqlbinlog.cc	2010-11-05 04:08:41 +0000
> @@ -995,12 +995,14 @@
>        }
>
>        ev->print(result_file, print_event_info);
> +      print_event_info->have_unflushed_events= TRUE;
>        /* Flush head and body cache to result_file */
>        if (stmt_end)
>        {
>          if
> (copy_event_cache_to_file_and_reinit(&print_event_info->head_cache, result_file)
> ||
>             
> copy_event_cache_to_file_and_reinit(&print_event_info->body_cache, result_file))
>            goto err;
> +        print_event_info->have_unflushed_events= FALSE;

(S1) I think the flag should be set *before* 
copy_event_cache_to_file_and_reinit. If there is an error, there will be 
an error message, so we don't need the warning. Also, the explanation in 
the warning message is not completely correct if there is an error (the 
reason is not a missing STMT_END_F event or an --end-position in the 
middle of a statement; the reason is the error).

>          goto end;
>        }
>        break;
> @@ -1499,7 +1501,7 @@
>    rc= (remote_opt ? dump_remote_log_entries(&print_event_info, logname) :
>         dump_local_log_entries(&print_event_info, logname));
>
> -  if (my_b_tell(&print_event_info.body_cache))
> +  if (print_event_info.have_unflushed_events)
>      warning("The range of printed events ends with a row event or "
>              "a table map event that does not have the STMT_END_F "
>              "flag set. This might be because the last statement "
>
> === modified file 'mysql-test/suite/rpl/r/rpl_packet.result'
> --- mysql-test/suite/rpl/r/rpl_packet.result	2010-11-01 05:40:27 +0000
> +++ mysql-test/suite/rpl/r/rpl_packet.result	2010-11-05 10:19:20 +0000
> @@ -75,14 +75,15 @@
>  INSERT INTO t1 VALUES (REPEAT('a', 2048));
>  # 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 displayed 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 #
> +# Record Read_Master_Log_Pos for the Table_map_log_event
> +SET @@global.max_allowed_packet=1048576;
> +SET @b55790_output.1= LOAD_FILE('MYSQLD_TMPDIR/b55790-mysqlbinlog.1');
> +WARNING: The range of printed events ends with a row event or a table map event that
> does not have the STMT_END_F flag set. This might be because the last statement was not
> fully written to the log, or because you are using a --stop-position or --stop-datetime
> that refers to an event in the middle of a statement. The event(s) from the partial
> statement have not been written to output.
> +SET @b55790_output.1= LOAD_FILE('MYSQLD_TMPDIR/b55790-mysqlbinlog.1');
>  WARNING: The range of printed events ends with a row event or a table map event that
> does not have the STMT_END_F flag set. This might be because the last statement was not
> fully written to the log, or because you are using a --stop-position or --stop-datetime
> that refers to an event in the middle of a statement. The event(s) from the partial
> statement have not been written to output.
>  ==== clean up ====
>  DROP TABLE t1;
>  SET @@global.max_allowed_packet= 1024;
>  SET @@global.net_buffer_length= 1024;
> +SET @@global.max_allowed_packet= 1024;
>  DROP TABLE t1;
>
> === modified file 'mysql-test/suite/rpl/t/rpl_packet.test'
> --- mysql-test/suite/rpl/t/rpl_packet.test	2010-11-01 05:40:27 +0000
> +++ mysql-test/suite/rpl/t/rpl_packet.test	2010-11-05 10:18:39 +0000
> @@ -188,21 +188,54 @@
>  --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 # Record Read_Master_Log_Pos for the Table_map_log_event
> +--let $table_map_log_pos= query_get_value("SHOW SLAVE STATUS", Read_Master_Log_Pos,
> 1)
>
> ---echo # Test the Table_map_log_event is displayed at Read_Master_Log_Pos by
> MYSQLBINLOG
>  --let $MYSQLD_DATADIR= `SELECT @@datadir`
> ---let $MYSQLD_TMPDIR= `select @@tmpdir`
> ---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 2> $MYSQLD_TMPDIR/warning.txt
> - | grep 'end_log_pos'
> - | tail -n 1;
> ---cat_file $MYSQLD_TMPDIR/warning.txt
> ---remove_file $MYSQLD_TMPDIR/warning.txt
> +--let $MYSQLD_TMPDIR= `SELECT @@tmpdir`
> +--let $start_pos= query_get_value("SHOW SLAVE STATUS", Relay_Log_Pos, 1)
> +--let $relay_log_file= query_get_value(SHOW SLAVE STATUS, Relay_Log_File, 1)
> +--let $outfile= $MYSQLD_TMPDIR/b55790-mysqlbinlog
> +--let $i= 2
> +
> +let $old_slave_max_allowed_packet= `SELECT @@global.max_allowed_packet`;
> +SET @@global.max_allowed_packet=1048576;
> +# Restart slave session for new settings to take effect.
> +--connect (slave2, localhost, root)
> +connection slave2;
> +while($i)
> +{
> +  if(`SELECT $i=1`)
> +  {
> +    --let $flags=--start-position=$start_pos
> +  }
> +
> +  if(`SELECT $i=2`)
> +  {
> +    --let $flags=--base64-output=decode-rows
> +  }
> +
> +  --exec $MYSQL_BINLOG $flags $MYSQLD_DATADIR/$relay_log_file 1> $outfile.1 2>
> $outfile.2

(S2)

  - I think we should pass --start-position both when $i==2 and when $i==1

  - We need to pass -v together with --base64-output=decode-rows.

So I think the above could be changed to:

if (i=1)
   flags=
if (i=2)
   flags= --base64-output=decode-rows -v
mysqlbinlog $flags --start-position=$start_pos ...

> +
> +  # Load outputs into a variable
> +  --replace_result $MYSQLD_TMPDIR MYSQLD_TMPDIR
> +  --eval SET @b55790_output.1= LOAD_FILE('$outfile.1')
> +
> +  # Check Relay log contains the Table_map_log_event that ends at
> Read_Master_Log_Pos
> +  if (!`SELECT INSTR(@b55790_output.1, 'end_log_pos $table_map_log_pos')`)

(S3) The output contains other events than the table_map. So just to be 
sure that no other event has this position, I would suggest to compare 
with 'end_log_pos $table_map_log_pos  Table_map'

> +  {
> +    --echo **** ERROR **** Table map 'end_log_pos $table_map_log_pos' NOT FOUND in
> mysqlbinlog output ($flags $outfile.1).

(S4) Good. Please also execute 'die' here.

> +  }
> +
> +  # Check the warning is caused
> +  --cat_file $outfile.2
> +
> +  # Remove unecessary files
> +  --remove_file $outfile.1
> +  --remove_file $outfile.2
> +
> +  --dec $i
> +}
>
>  --echo ==== clean up ====
>  connection master;
> @@ -211,6 +244,7 @@
>  eval SET @@global.net_buffer_length= $old_net_buffer_length;
>  # slave is stopped
>  connection slave;
> +eval SET @@global.max_allowed_packet= $old_slave_max_allowed_packet;
>  DROP TABLE t1;
>
>  # End of tests
>
> === modified file 'sql/log_event.h'
> --- sql/log_event.h	2010-10-21 13:05:32 +0000
> +++ sql/log_event.h	2010-11-05 03:51:58 +0000
> @@ -697,7 +697,8 @@
>      close_cached_file(&body_cache);
>    }
>    bool init_ok() /* tells if construction was successful */
> -    { return my_b_inited(&head_cache) && my_b_inited(&body_cache);
> }
> +    { return my_b_inited(&head_cache) && my_b_inited(&body_cache)
> &&
> +             !(have_unflushed_events= FALSE); }

(S5) I think the flag should be set in the constructor, 
st_print_event_info::st_print_event_info() in log_event.cc

>
>
>    /* Settings on how to print the events */
> @@ -725,6 +726,8 @@
>     */
>    IO_CACHE head_cache;
>    IO_CACHE body_cache;
> +  /* Indicate if the body cache has unflushed events */
> +  bool have_unflushed_events;
>  } PRINT_EVENT_INFO;
>  #endif

Thread
BUG#56790 review (2)Sven Sandberg5 Nov
  • Re: BUG#56790 review (2)Daogang Qu6 Nov