maria-developers team mailing list archive

[Kristian Nielsen <knielsen@xxxxxxxxxxxxxxx>]

Hi Serg,

Just wanted to be sure you saw this. The async binlogging of the checkpoint
event after MDEV-532 means a few test cases need to wait for the event to be
logged, or they will get races causing failures with result difference in SHOW
BINLOG EVENTS or similar. Typically after running FLUSH LOGS.

I fixed the ones I found already. But it is possible that a few others will
pop up, and it is useful that someone else than me knows how to fix (so I'm
picking on you as the reviewer :-).

As seen in the patch, it's just a matter of including the file
include/wait_for_binlog_checkpoint.inc in the appropriate place.

 - Kristian.

knielsen@xxxxxxxxxxxxxxx writes:

> At http://bazaar.launchpad.net/~maria-captains/maria/10.0
>
> ------------------------------------------------------------
> revno: 3449
> revision-id: knielsen@xxxxxxxxxxxxxxx-20121217114911-m3qv20xmk7htleez
> parent: igor@xxxxxxxxxxxx-20121217004919-xgon81zqncwimr3m
> committer: knielsen@xxxxxxxxxxxxxxx
> branch nick: mariadb-10.0-base
> timestamp: Mon 2012-12-17 12:49:11 +0100
> message:
>   MDEV-532: Fix some race conditions in test cases.
>   
>   With MDEV-532, the binlog_checkpoint event is logged asynchronously
>   from a binlog background thread. This causes some sporadic failures
>   in some test cases whose output depends on order of events in
>   binlog.
>   
>   Fix using an include file that waits until the binlog checkpoint
>   event has been logged before proceeding with the test case.
> === modified file 'mysql-test/extra/rpl_tests/rpl_insert_delayed.test'
> --- a/mysql-test/extra/rpl_tests/rpl_insert_delayed.test	2012-09-22 14:11:40 +0000
> +++ b/mysql-test/extra/rpl_tests/rpl_insert_delayed.test	2012-12-17 11:49:11 +0000
> @@ -94,8 +94,10 @@ if  (`SELECT @@global.binlog_format = 'S
>    #flush the logs before the test
>    connection slave;
>    FLUSH LOGS;
> +  source include/wait_for_binlog_checkpoint.inc;
>    connection master;
>    FLUSH LOGS;
> +  source include/wait_for_binlog_checkpoint.inc;
>  }
>  
>  CREATE TABLE t1(a int, UNIQUE(a));
>
> === modified file 'mysql-test/extra/rpl_tests/rpl_log.test'
> --- a/mysql-test/extra/rpl_tests/rpl_log.test	2011-10-19 19:45:18 +0000
> +++ b/mysql-test/extra/rpl_tests/rpl_log.test	2012-12-17 11:49:11 +0000
> @@ -43,6 +43,7 @@ let $binlog_limit= 1,4;
>  source include/show_binlog_events.inc;
>  let $binlog_limit=;
>  flush logs;
> +--source include/wait_for_binlog_checkpoint.inc
>  
>  # We need an extra update before doing save_master_pos.
>  # Otherwise, an unlikely scenario may occur:
>
> === modified file 'mysql-test/extra/rpl_tests/rpl_show_relaylog_events.inc'
> --- a/mysql-test/extra/rpl_tests/rpl_show_relaylog_events.inc	2011-01-13 14:31:37 +0000
> +++ b/mysql-test/extra/rpl_tests/rpl_show_relaylog_events.inc	2012-12-17 11:49:11 +0000
> @@ -41,8 +41,10 @@ INSERT INTO t1 VALUES (3);
>  #
>  
>  FLUSH LOGS;
> +--source include/wait_for_binlog_checkpoint.inc
>  -- connection master
>  FLUSH LOGS;
> +--source include/wait_for_binlog_checkpoint.inc
>  DROP TABLE t1;
>  
>  --let $is_relay_log= 0
>
> === added file 'mysql-test/include/wait_for_binlog_checkpoint.inc'
> --- a/mysql-test/include/wait_for_binlog_checkpoint.inc	1970-01-01 00:00:00 +0000
> +++ b/mysql-test/include/wait_for_binlog_checkpoint.inc	2012-12-17 11:49:11 +0000
> @@ -0,0 +1,53 @@
> +# include/wait_for_binlog_checkpoint.inc
> +#
> +# SUMMARY
> +#
> +#    Wait until binlog checkpoint has been logged for current binlog file.
> +#    This is useful to avoid races with output difference for binlog
> +#    checkpoints, as these are logged asynchronously from the binlog
> +#    background thread.
> +#
> +# USAGE:
> +#
> +#    --source include/wait_for_binlog_checkpoint.inc
> +
> +let $_wait_count= 300;
> +
> +let $_found= 0;
> +
> +while ($_wait_count)
> +{
> +  dec $_wait_count;
> +  let $_cur_binlog= query_get_value(SHOW MASTER STATUS, File, 1);
> +  let $_more= 1;
> +  let $_row= 1;
> +  while ($_more)
> +  {
> +    let $_event= query_get_value(SHOW BINLOG EVENTS IN "$_cur_binlog", Event_type, $_row);
> +    if ($_event == "No such row")
> +    {
> +      let $_more= 0;
> +    }
> +    if ($_event == "Binlog_checkpoint")
> +    {
> +      let $_info= query_get_value(SHOW BINLOG EVENTS IN "$_cur_binlog", Info, $_row);
> +      if (`SELECT INSTR("$_info", "$_cur_binlog") != 0`)
> +      {
> +        let $_more= 0;
> +        let $_wait_count= 0;
> +        let $_found= 1;
> +      }
> +    }
> +    inc $_row;
> +  }
> +  if ($_wait_count)
> +  {
> +    real_sleep 0.1;
> +  }
> +}
> +
> +if (!$_found)
> +{
> +  eval SHOW BINLOG EVENTS IN "$_cur_binlog";
> +  --die ERROR: failed while waiting for binlog checkpoint $_cur_binlog
> +}
>
> === modified file 'mysql-test/suite/innodb/t/binlog_consistent.test'
> --- a/mysql-test/suite/innodb/t/binlog_consistent.test	2012-02-07 15:22:36 +0000
> +++ b/mysql-test/suite/innodb/t/binlog_consistent.test	2012-12-17 11:49:11 +0000
> @@ -72,6 +72,7 @@ connection con3;
>  --echo # Connection con3
>  COMMIT;
>  FLUSH LOGS;
> +--source include/wait_for_binlog_checkpoint.inc
>  
>  connection default;
>  --echo # Connection default
>
> === modified file 'mysql-test/suite/multi_source/multisource.test'
> --- a/mysql-test/suite/multi_source/multisource.test	2012-10-04 20:36:17 +0000
> +++ b/mysql-test/suite/multi_source/multisource.test	2012-12-17 11:49:11 +0000
> @@ -169,6 +169,7 @@ select * from db2.t1;
>  
>  --connection master1
>  flush logs;
> +--source include/wait_for_binlog_checkpoint.inc
>  --save_master_pos
>  --connection slave
>  --sync_with_master 0, 'master1'
>
> _______________________________________________
> commits mailing list
> commits@xxxxxxxxxxx
> https://lists.askmonty.org/cgi-bin/mailman/listinfo/commits