Re: Review for WL#4091

[He Zhenxing]

on 2008-02-28 Thu 13:05 +0300，Serge Kozlov wrote：
> He Zhenxing wrote:
> > Hi Serge
> > 
> > On 2008-02-27 Wed 13:09 +0300，Serge Kozlov wrote：
> >> Hello.
> >>
> >> See comments below and please send me your final conclusion (approved 
> >> with suggested changes, not approved)
> >>
> > 
> > approved with suggested changes
> > 
> >> He Zhenxing wrote:
> >>> Hi Serge
> >>>
> >>> Thank you for your work, please read comments below.
> >>>
> >>> On 2008-02-24 Sun 02:10 +0300，Serge Kozlov wrote：
> >>>> Hi, Magnus and Zhenxing
> >>>>
> >>>> Could you review patch for WL#4091 (based in LLD, part 4) removing
> sleeps?
> >>> What is LLD? I'd like to have a look at it.
> >> skozlov: LLD - Low Level Design :) of WL.
> >>
> > 
> > thanks!
> > 
> >>>> Thanks!
> >>>>
> >>>>
> >>>> # This is a BitKeeper generated diff -Nru style patch.
> >>>> #
> >>>> # ChangeSet
> >>>> #   2008/02/24 01:20:11+03:00 skozlov@stripped
> >>>> #   WL#4091, LLD/4, removing sleeps
> >>>> #
> >>>> # mysql-test/include/wait_for_binlog_event.inc
> >>>> #   2008/02/24 01:20:01+03:00 skozlov@stripped +35 -0
> >>>> #   new primitive: waiting for a event in SHOW BINLOG EVENTS output
> >>>> #
> >>>> # mysql-test/include/wait_for_binlog_event.inc
> >>>> #   2008/02/24 01:20:01+03:00 skozlov@stripped +0 -0
> >>>> #
> >>>> # mysql-test/suite/rpl/r/rpl_flushlog_loop.result
> >>>> #   2008/02/24 01:19:58+03:00 skozlov@stripped +3 -3
> >>>> #   updated result file
> >>>> #
> >>>> # mysql-test/suite/rpl/r/rpl_row_view01.result
> >>>> #   2008/02/24 01:19:59+03:00 skozlov@stripped +3 -0
> >>>> #   updated result file
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_change_master.test
> >>>> #   2008/02/24 01:19:59+03:00 skozlov@stripped +3 -1
> >>>> #   replacing sleep
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_drop_temp.test
> >>>> #   2008/02/24 01:19:59+03:00 skozlov@stripped +9 -3
> >>>> #   replacing sleep
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_flushlog_loop.test
> >>>> #   2008/02/24 01:20:00+03:00 skozlov@stripped +22 -3
> >>>> #   replacing sleep
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_relayspace.test
> >>>> #   2008/02/24 01:20:00+03:00 skozlov@stripped +5 -16
> >>>> #   use external source for waiting of a query
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_row_view01.test
> >>>> #   2008/02/24 01:20:00+03:00 skozlov@stripped +12 -4
> >>>> #   replacing sleep
> >>>> #
> >>>> # mysql-test/suite/rpl/t/rpl_trunc_temp.test
> >>>> #   2008/02/24 01:20:00+03:00 skozlov@stripped +6 -1
> >>>> #   replacing sleep
> >>>> #
> >>>> diff -Nru a/mysql-test/include/wait_for_binlog_event.inc 
> >>>> b/mysql-test/include/wait_for_binlog_event.inc
> >>>> --- /dev/null	Wed Dec 31 16:00:00 196900
> >>>> +++ b/mysql-test/include/wait_for_binlog_event.inc	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> @@ -0,0 +1,35 @@
> >>>> +# include/wait_for_binlog_event.inc
> >>>> +#
> >>>> +# SUMMARY
> >>>> +#
> >>>> +#    Waits until SHOW BINLOG EVENTS has returned in last event a 
> >>>> specified substring.
> >>>> +#
> >>>> +# USAGE
> >>>> +#
> >>>> +#    let $wait_binlog_event= DROP;
> >>>> +#    --source include/wait_for_binlog_event.inc
> >>>> +
> >>>> +let $binlog_event_counter= 300;
> >>>> +
> >>>> +let $binlog_event_last= ;
> >>>> +
> >>>> +while (`SELECT INSTR("$binlog_event_last","$wait_binlog_event") =
> 0`)
> >>>> +{
> >>>> +  dec $binlog_event_counter;
> >>>> +  if (!$binlog_event_counter)
> >>>> +  {
> >>>> +    --echo ERROR: failed while waiting for $binlog_event in binlog
> >>>> +    SHOW BINLOG EVENTS;
> >>>> +    exit;
> >>>> +  }
> >>>> +  sleep 0.1;
> >>>> +  let $binlog_int_counter= 1;
> >>>> +  let $binlog_int_event= query_get_value(SHOW BINLOG EVENTS, Info,
> 
> >>>> $binlog_int_counter);
> >>>> +  let $binlog_event_last= $binlog_int_event;
> >>>> +  while (`SELECT "$binlog_int_event" != "No such row"`)
> >>>> +  {
> >>>> +    inc $binlog_int_counter;
> >>>> +    let $binlog_event_last= $binlog_int_event;
> >>>> +    let $binlog_int_event= query_get_value(SHOW BINLOG EVENTS,
> Info, 
> >>>> $binlog_int_counter);
> >>>> +  }
> >>>> +}
> >>> I like this idea, but I have some comments on the implimentation.
> >>>
> >>> I think we should use `real_sleep' here, `sleep' can be affected
> >>> by --sleep option of mysqltest.
> >>>
> >>> The `sleep' will at least be run once, even if the event we are
> >>> waiting for has already been there. I think unnecessary delay
> >>> should be prevented.
> >>>
> >>> Whenever we restart the outer while loop, we start searching from
> >>> the beginning of all the binlog events. this is not necessary, we
> >>> should start from where we stopped in the previous loop.
> >> skozlov: OK
> >>
> >>> `exit' will end the test normally, use `die' instead.  
> >> skozlov: Agree, Magnus said same :)
> >>
> >>> I would suggest renaming following internal variables:
> >>>   `binlog_event_counter' -> `_loop_count'
> >>>   `binlog_int_counter' -> `_event_pos'
> >>>   `binlog_int_event' -> `_event'
> >>>   `binlog_last_event' -> `_last_event'
> >> OK.
> >>
> >>>> diff -Nru a/mysql-test/suite/rpl/r/rpl_flushlog_loop.result 
> >>>> b/mysql-test/suite/rpl/r/rpl_flushlog_loop.result
> >>>> --- a/mysql-test/suite/rpl/r/rpl_flushlog_loop.result	2008-02-24 
> >>>> 01:44:04 +03:00
> >>>> +++ b/mysql-test/suite/rpl/r/rpl_flushlog_loop.result	2008-02-24 
> >>>> 01:44:04 +03:00
> >>>> @@ -23,7 +23,7 @@
> >>>>   let $result_pattern= 
> >>>>
> '%127.0.0.1%root%slave-bin.000001%slave-bin.000001%Yes%Yes%0%0%None%' ;
> >>>>
> >>>>   --source include/wait_slave_status.inc
> >>>> -flush logs;
> >>>> +FLUSH LOGS;
> >>>>   SHOW SLAVE STATUS;
> >>>>   Slave_IO_State	#
> >>>>   Master_Host	127.0.0.1
> >>>> @@ -31,7 +31,7 @@
> >>>>   Master_Port	SLAVE_PORT
> >>>>   Connect_Retry	60
> >>>>   Master_Log_File	slave-bin.000001
> >>>> -Read_Master_Log_Pos	216
> >>>> +Read_Master_Log_Pos	POSITION
> >>>>   Relay_Log_File	#
> >>>>   Relay_Log_Pos	#
> >>>>   Relay_Master_Log_File	slave-bin.000001
> >>>> @@ -46,7 +46,7 @@
> >>>>   Last_Errno	0
> >>>>   Last_Error	
> >>>>   Skip_Counter	0
> >>>> -Exec_Master_Log_Pos	216
> >>>> +Exec_Master_Log_Pos	POSITION
> >>>>   Relay_Log_Space	#
> >>>>   Until_Condition	None
> >>>>   Until_Log_File	
> >>>> diff -Nru a/mysql-test/suite/rpl/r/rpl_row_view01.result 
> >>>> b/mysql-test/suite/rpl/r/rpl_row_view01.result
> >>>> --- a/mysql-test/suite/rpl/r/rpl_row_view01.result	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> +++ b/mysql-test/suite/rpl/r/rpl_row_view01.result	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> @@ -13,6 +13,7 @@
> >>>>   DROP TABLE IF EXISTS mysqltest1.t1;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t2;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t4;
> >>>> +DROP TABLE IF EXISTS mysqltest1.t10;
> >>>>   CREATE TABLE mysqltest1.t1 (a INT, c CHAR(6),PRIMARY KEY(a));
> >>>>   CREATE TABLE mysqltest1.t2 (a INT, c CHAR(6),PRIMARY KEY(a));
> >>>>   CREATE TABLE mysqltest1.t3 (a INT, c CHAR(6), c2 CHAR(6), PRIMARY
> KEY(a));
> >>>> @@ -35,6 +36,7 @@
> >>>>   1	Thank	GOD
> >>>>   2	it	is
> >>>>   3	Friday	TGIF
> >>>> +CREATE TABLE mysqltest1.t10 (a INT, PRIMARY KEY(a));
> >>>>   SELECT * FROM mysqltest1.v2;
> >>>>   qty	price	value
> >>>>   3	50	150
> >>>> @@ -98,4 +100,5 @@
> >>>>   DROP TABLE IF EXISTS mysqltest1.t1;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t2;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t4;
> >>>> +DROP TABLE IF EXISTS mysqltest1.t10;
> >>>>   DROP DATABASE mysqltest1;
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_change_master.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_change_master.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_change_master.test	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_change_master.test	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> @@ -15,8 +15,10 @@
> >>>>   insert into t1 values(1);
> >>>>   insert into t1 values(2);
> >>>>   save_master_pos;
> >>>> +let $slave_param= Read_Master_Log_Pos;
> >>>> +let $slave_param_value= query_get_value(SHOW MASTER STATUS,
> Position, 1);
> >>>>   connection slave;
> >>>> ---real_sleep 3 # wait for I/O thread to have read updates
> >>>> +source include/wait_for_slave_param.inc;
> >>> Very cool! I think this idea can also be used for waiting for a given
> >>> statement to be executed by the slave.
> >>>
> >>>>   stop slave;
> >>>>   source include/show_slave_status2.inc;
> >>>>   change master to master_user='root';
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_drop_temp.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_drop_temp.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_drop_temp.test	2008-02-24 01:44:04
> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_drop_temp.test	2008-02-24 01:44:04
> +03:00
> >>>> @@ -6,19 +6,25 @@
> >>>>   # to work around NDB's issue with temp tables
> >>>>   ##############################################
> >>>>   source include/master-slave.inc;
> >>>> +source include/have_binlog_format_mixed_or_statement.inc;
> >>>> +
> >>>>   --disable_warnings
> >>>>   create database if not exists mysqltest;
> >>>>   --enable_warnings
> >>>>
> >>>>   create temporary table mysqltest.t1 (n int)ENGINE=MyISAM;
> >>>>   create temporary table mysqltest.t2 (n int)ENGINE=MyISAM;
> >>>> -sync_slave_with_master;
> >>>> +
> >>>>   connection master;
> >>>>   disconnect master;
> >>>> +
> >>>> +connection master1;
> >>>> +# Wait until drop of temp tables appears in binlog
> >>>> +let $wait_binlog_event= DROP;
> >>>> +source include/wait_for_binlog_event.inc;
> >>>> +
> >>> I think this only make sure that the DROP statement has been written
> >>> into master's binlog, should add a `sync_slave_with_master' to make
> sure
> >>> it has been replicated to the slave, otherwise there is a very slight
> >>> chance that the test will fail because the DROP statement has not been
> >>> replicated yet.
> >> No, you're not right :). In this case we cannot sync slave with master 
> >> because connection lost. We cannot sync via connection to master1 
> >> because it doesn't have this event. We can wait this event only. All 
> >> these test cases were not fixed as others because have sleep for special 
> >> non-standard cases.
> >>
> > 
> > I doubt it :) connection master and connection master1 are connected to
> > the same server, you can check this in include/master-slave.inc, so how
> > could connection master1 doesn't have this event? I have test the
> > following:
> > 
> 
> We are using there temp tables. The property of temp tables is working 
> inside a session (they are visible inside session only). If you close 
> session to master then all temp tables (associated to that session) 
> should be dropped. Another session to master has no access to this 
> tables. Main purpose of the test case is checking  that master sends 
> DROP TEMP TABLE to slave. We can't control that event. But we can wait 
> it in binlog on master, sync slave with master and make sure that all 
> temp tables on slave closed too.
> 

The temp tables are only visible inside the session in which is created,
but the DROP statement that drops the temp tables are visible to all
sessions, and in fact you used connection master1 to wait for the DROP
statement to appear, this means the DROP event is visible to all
sessions or connections.

> 
> 
> > ------------------- rpl_tmp.test ------------------------------
> > source include/master-slave.inc;
> > 
> > create table t1 (a int);
> > 
> > insert into t1 values (1);
> > insert into t1 values (2);
> > insert into t1 values (3);
> > 
> > query_vertical show master status;
> > 
> > disconnect master;
> > connection master1;
> > 
> > query_vertical show master status;
> > sync_slave_with_master;
> > 
> > select * from t1;
> > -----------------------------------------------------------
> > 
> > and this is the result
> > 
> > ----------------------- rpl_tmp.result --------------------
> > stop slave;
> > drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
> > reset master;
> > reset slave;
> > drop table if exists t1,t2,t3,t4,t5,t6,t7,t8,t9;
> > start slave;
> > create table t1 (a int);
> > insert into t1 values (1);
> > insert into t1 values (2);
> > insert into t1 values (3);
> > show master status;
> > File	master-bin.000001
> > Position	456
> > Binlog_Do_DB	
> > Binlog_Ignore_DB	
> > show master status;
> > File	master-bin.000001
> > Position	456
> > Binlog_Do_DB	
> > Binlog_Ignore_DB	
> > select * from t1;
> > a
> > 1
> > 2
> > 3
> > ----------------------------------------------------------
> > 
> > I see no problem, do I miss something here?
> > 
> >>>>   connection slave;
> >>>> ---real_sleep 3 # time for DROP to be written
> >>>>   show status like 'Slave_open_temp_tables';
> >>>> -
> >>>>   # Cleanup
> >>>>   connection default;
> >>>>   drop database mysqltest;
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_flushlog_loop.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_flushlog_loop.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_flushlog_loop.test	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_flushlog_loop.test	2008-02-24
> 01:44:04 
> >>>> +03:00
> >>>> @@ -35,12 +35,31 @@
> >>>>   #
> >>>>   #  Flush logs of slave
> >>>>   #
> >>>> -flush logs;
> >>>> -sleep 5;
> >>>> +# Create full loop by following way:
> >>>> +# 1. Insert into t1 on master (1st).
> >>>> +# 2. Insert into t1 on slave (2nd) when the event (1st) for t1
> replicated.
> >>>> +# 3. Master waits until the event (2nd) for t1 will be replicated.
> >>>> +
> >>>> +--disable_query_log
> >>>> +CREATE TABLE t1 (a INT KEY) ENGINE= MyISAM;
> >>>> +INSERT INTO t1 VALUE(1);
> >>>> +--enable_query_log
> >>>> +FLUSH LOGS;
> >>>> +connection slave;
> >>>> +let $wait_condition= SELECT COUNT(*) = 1 FROM t1;
> >>>> +-- source include/wait_condition.inc
> >>>> +--disable_query_log
> >>>> +INSERT INTO t1 VALUE(2);
> >>>> +--enable_query_log
> >>>> +connection master;
> >>>> +let $wait_condition= SELECT COUNT(*) = 2 FROM t1;
> >>>> +-- source include/wait_condition.inc
> >>>> +--enable_query_log
> >>>>
> >>>>   #
> >>>>   #  Show status of slave
> >>>>   #
> >>>> ---replace_result $SLAVE_MYPORT SLAVE_PORT
> >>>> +let $pos= query_get_value(SHOW SLAVE STATUS, Read_Master_Log_Pos,
> 1);
> >>>> +--replace_result $SLAVE_MYPORT SLAVE_PORT $pos POSITION
> >>>>   --replace_column 1 # 8 # 9 # 16 # 23 # 33 # 34 # 35 #
> >>>>   --query_vertical SHOW SLAVE STATUS
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_relayspace.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_relayspace.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_relayspace.test	2008-02-24 01:44:04
> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_relayspace.test	2008-02-24 01:44:04
> +03:00
> >>>> @@ -14,23 +14,12 @@
> >>>>   reset slave;
> >>>>   start slave io_thread;
> >>>>   # Give the I/O thread time to block.
> >>>> -let $run= 1;
> >>>> -let $counter= 300;
> >>>> -while ($run)
> >>>> -{
> >>>> -  let $io_state= query_get_value("SHOW SLAVE STATUS",
> Slave_IO_State, 1);
> >>>> -  if (`SELECT '$io_state' = 'Waiting for the slave SQL thread to
> free 
> >>>> enough relay log space'`){
> >>>> -    let $run= 0;
> >>>> -  }
> >>>> -  sleep 0.1;
> >>>> -  if (!$counter){
> >>>> -   --echo "Failed while waiting for slave IO thread block"
> >>>> -   SHOW SLAVE STATUS;
> >>>> -   exit;
> >>>> -  }
> >>>> -  dec $counter;
> >>>> +let $io_state= query_get_value(SHOW SLAVE STATUS, Slave_IO_State,
> 1);
> >>>> +if (`SELECT '$io_state' != 'Waiting for master to send event'`) {
> >>>> +  let $slave_param= Slave_IO_State;
> >>>> +  let $slave_param_value= Waiting for the slave SQL thread to free
> 
> >>>> enough relay log space;
> >>>> +  source include/wait_for_slave_param.inc;
> >>>>   }
> >>> I don't quit understand why you first check if the state is not
> "Waiting
> >>> for master to send event". Could you please explain this?
> >> Sometimes status of slave changes very fast. 'Waiting for master to send 
> >> event' status appears *after* 'Waiting for the slave SQL thread to free 
> >>   enough relay log space'
> >>
> > 
> > If my understanding is correct, I think for this case, the SQL thread
> > will enter a dead lock at the status "Waiting ... relay log space", so I
> > think there is not a possibility that the status will be changed to
> > "Waiting for master to send event" *after* "Waiting ... relay log
> > space". On contray I think, the only possibility that we can get
> > "Waiting for master to send event" status is because the IO thread just
> > started, and the first event has not been sent to the slave yet, so the
> > "Waiting for master to send event" can only appear *before* "Waiting ...
> > relay log space".
> > 

What's you opion about the above comment?

> >>>> -sleep 2;
> >>>>   # A bug caused the I/O thread to refuse stopping.
> >>>>   stop slave io_thread;
> >>>>   reset slave;
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_row_view01.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_row_view01.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_row_view01.test	2008-02-24 01:44:04
> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_row_view01.test	2008-02-24 01:44:04
> +03:00
> >>>> @@ -23,6 +23,7 @@
> >>>>   DROP TABLE IF EXISTS mysqltest1.t1;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t2;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t4;
> >>>> +DROP TABLE IF EXISTS mysqltest1.t10;
> >>>>
> >>>>   # Begin test section 1
> >>>>   CREATE TABLE mysqltest1.t1 (a INT, c CHAR(6),PRIMARY KEY(a));
> >>>> @@ -43,12 +44,18 @@
> >>>>
> >>>>   SELECT * FROM mysqltest1.v2;
> >>>>   SELECT * FROM mysqltest1.v1;
> >>>> -# Had to add a sleep for use with NDB
> >>>> +
> >>>> +
> >>>> +# Had to add a waiting for use with NDB
> >>>>   # engine. Injector thread would have not
> >>>> -# populated biblog and data would not be on
> >>>> +# populated binlog and data would not be on
> >>>>   # the slave.
> >>>> -sleep 10;
> >>>> -sync_slave_with_master;
> >>>> +
> >>>> +CREATE TABLE mysqltest1.t10 (a INT, PRIMARY KEY(a));
> >>>> +let $wait_binlog_event= CREATE TABLE mysqltest1.t10;
> >>>> +-- source include/wait_for_binlog_event.inc
> >>>> +--sync_master_with_slave
> >>> must be a typo of `sync_slave_with_master'
> >> skozlov: of course :)
> >>>> +
> >>>>   SELECT * FROM mysqltest1.v2;
> >>>>   SELECT * FROM mysqltest1.v1;
> >>>>   connection master;
> >>>> @@ -82,6 +89,7 @@
> >>>>   DROP TABLE IF EXISTS mysqltest1.t1;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t2;
> >>>>   DROP TABLE IF EXISTS mysqltest1.t4;
> >>>> +DROP TABLE IF EXISTS mysqltest1.t10;
> >>>>   DROP DATABASE mysqltest1;
> >>>>   sync_slave_with_master;
> >>>>
> >>>> diff -Nru a/mysql-test/suite/rpl/t/rpl_trunc_temp.test 
> >>>> b/mysql-test/suite/rpl/t/rpl_trunc_temp.test
> >>>> --- a/mysql-test/suite/rpl/t/rpl_trunc_temp.test	2008-02-24 01:44:04
> +03:00
> >>>> +++ b/mysql-test/suite/rpl/t/rpl_trunc_temp.test	2008-02-24 01:44:04
> +03:00
> >>>> @@ -27,7 +27,12 @@
> >>>>
> >>>>   # Disconnect the master, temp table on slave should dissapear
> >>>>   disconnect master;
> >>>> ---real_sleep 3 # time for DROP to be read by slave
> >>>> +
> >>>> +connection master1;
> >>>> +# Wait until drop of temp tables appers in binlog
> >>>> +let $wait_binlog_event= DROP;
> >>>> +source include/wait_for_binlog_event.inc;
> >>>> +
> >>>>   connection slave;
> >>>>   show status like 'Slave_open_temp_tables';
> >>>>
> >>>>
> >>>
> >>
> > 
> > 
> 
>