Re: bk commit into 5.2 tree (cmiller:1.2563) BUG#28760

[Rafal Somla]

Hi Chad,

See my comments inlined below.

Rafal

Chad MILLER wrote:
> Below is the list of changes that have just been committed into a local
> 5.2 repository of cmiller. When cmiller does a push these changes will
> be propagated to the main repository and, within 24 hours after the
> push, to the public repository.
> For information on how to access the public repository
> see http://dev.mysql.com/doc/mysql/en/installing-source-tree.html
> 
> ChangeSet@stripped, 2007-09-10 18:29:14-04:00, cmiller@stripped +9 -0
>   Bug#28760 / WL#344: Delayed replication
>   
>   Contributed by Kay Roepke, CLA#50.
>   
> 
>   mysql-test/suite/rpl/r/rpl_delay.result@stripped, 2007-09-10 18:28:30-04:00,
> cmiller@stripped +39 -0
>     New replication delay test.  Verify that events are applied after 
>     the requested delay.
> 
>   mysql-test/suite/rpl/r/rpl_delay.result@stripped, 2007-09-10 18:28:30-04:00,
> cmiller@stripped +0 -0
> 
>   mysql-test/suite/rpl/t/rpl_delay.test@stripped, 2007-09-10 18:28:30-04:00,
> cmiller@stripped +125 -0
>     New replication delay test.  Verify that events are applied after 
>     the requested delay.
> 
>   mysql-test/suite/rpl/t/rpl_delay.test@stripped, 2007-09-10 18:28:30-04:00,
> cmiller@stripped +0 -0
> 
>   sql/lex.h@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +1 -0
>     Add new master_delay symbol.
> 
>   sql/rpl_mi.cc@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +14 -4
>     Load the delay time stored in the master info file, and write out 
>     the new variable to the info file.
> 
>   sql/rpl_mi.h@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +2 -0
>     Create a varible to hold the delay value in the master info file.
>

I think delay value should be kept in RELAY_LOG_INFO structure. MASTER_INFO
describes characteristics of the master to which slave is connected and other
information relevant for the IO thread. RELAY_LOG_INFO is about parameters of
the slave and is used by SQL thread. I think the delay belongs there.

>   sql/slave.cc@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +33 -0
>     Add a "Delay" column to the SHOW table.
>     
>     Delay (most) events if a delay is set and the time from now to
>     the expiration of the delay from its start is greater than now.
> 
>   sql/sql_lex.h@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +1 -0
>     Define a new field in the master_info structure to hold the delay.
> 
>   sql/sql_repl.cc@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +2 -0
>     For the CHANGE MASTER command, pull the delay value from the parser
>     info into the master info.
> 
>   sql/sql_yacc.yy@stripped, 2007-09-10 18:28:30-04:00, cmiller@stripped +7 -0
>     Define a new token, MASTER_DELAY.
> 
>     Store the delay value in a place where we can use it later.
> 

> diff -Nrup a/mysql-test/suite/rpl/r/rpl_delay.result
> b/mysql-test/suite/rpl/r/rpl_delay.result
> --- /dev/null	Wed Dec 31 16:00:00 196900
> +++ b/mysql-test/suite/rpl/r/rpl_delay.result	2007-09-10 18:28:30 -04:00
> @@ -0,0 +1,39 @@
> +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;
> +reset master;
> +drop table if exists delay_test;
> +Warnings:
> +Note	1051	Unknown table 'delay_test'
> +create table delay_test ( c1 int );
> +select count(*) as c from delay_test;
> +c
> +0
> +insert into delay_test values (1);
> +select count(*) as c from delay_test;
> +delete from delay_test;
> +change master to master_delay=5;
> +ERROR HY000: This operation cannot be performed with a running slave; run STOP SLAVE
> first
> +stop slave;
> +change master to master_delay=5;
> +start slave;
> +delete from delay_test;
> +insert into delay_test values (1);
> +insert into delay_test values (2);
> +insert into delay_test values (3);
> +insert into delay_test values (4);
> +select c1 from delay_test order by c1;
> +c1
> +select c1 from delay_test order by c1;
> +c1
> +1
> +2
> +3
> +4
> +stop slave;
> +change master to master_delay=0;
> +start slave;
> +drop table delay_test;

> diff -Nrup a/mysql-test/suite/rpl/t/rpl_delay.test
> b/mysql-test/suite/rpl/t/rpl_delay.test
> --- /dev/null	Wed Dec 31 16:00:00 196900
> +++ b/mysql-test/suite/rpl/t/rpl_delay.test	2007-09-10 18:28:30 -04:00
> @@ -0,0 +1,125 @@
> +source include/master-slave.inc;
> +disable_warnings;
> +sync_slave_with_master;
> +reset master;

Is this correct? I though 'sync_slave_with_master' is leaving us in the slave
connection and then 'reset master' is not doing what one could expect.

> +enable_warnings;
> +
> +
> +##
> +#
> +# First test:  Create a table, delay the slave, insert into the master, and die
> +# if the slave presents that data before the delay has elapsed.
> +#
> +##
> +
> +# This is an arbitrary value.  Smaller means that the test could yeild false
> +# passing results.  Larger means unnecessary delay in the tests.
> +let $delay=5;
> +###
> +
> +# Create work table
> +connection master;
> +drop table if exists delay_test;
> +create table delay_test ( c1 int );
> +select count(*) as c from delay_test;
> +insert into delay_test values (1);
> +
> +# Wait until the table is replicated.  (Just being paranoid.)
> +connection slave;

Use sync_slave_with_master to ensure that all is replicated.

> +let $t = 0;
> +let $time_remaining = 600;
> +
> +disable_result_log;
> +error 0,ER_NO_SUCH_TABLE;
> +select count(*) as c from delay_test;
> +enable_result_log;
> +while ($mysql_errno == 1146)

Is 1146 supposed to be the value of ER_NO_SUCH_TABLE? If yes then this test
script will break as soon as new error codes are added to mysqld...

> +{
> +  if (!$time_remaining)
> +  {
> +    echo $t, $time_remaining;
> +    exit;
> +    die "Table DDL replication took more than a minute!  $i";
> +  }
> +
> +  # Ten queries per second shouldn't slow down the server.  Fast is good, but
> +  # too fast causes delays.
> +  sleep 0.1;
> +  inc $t;
> +  dec $time_remaining;
> +
> +  disable_result_log;
> +  error 0,ER_NO_SUCH_TABLE;
> +  select count(*) as c from delay_test;
> +  enable_result_log;
> +}
> +delete from delay_test;

Hmm, if all the code above is to ensure that the table was replicated to slave,
I think it should be simply done with sync_slave_with_master

> +
> +# While we're connected to the slave, verify that we can't change the value
> +# without shutting it down.
> +error ER_SLAVE_MUST_STOP;
> +eval change master to master_delay=$delay;
> +
> +# Actually change the delay value.
> +stop slave;
> +eval change master to master_delay=$delay;
> +start slave;
> +
> +# Insert values into the master.
> +connection master;
> +delete from delay_test;
> +insert into delay_test values (1);
> +insert into delay_test values (2);
> +insert into delay_test values (3);
> +insert into delay_test values (4);
> +
> +connection slave;
> +let $elapsed = 0;
> +let $row_count = 0;
> +let $time_remaining = 60;
> +
> +# Assert that there is nothing in the table yet.
> +select c1 from delay_test order by c1;

Why not more explicit "select count(*) from delay_test"?

> +
> +# Time how long it takes to arrive in the table.
> +while (!$row_count)
> +{
> +  sleep 1;
> +  let $row_count = query_get_value("select count(*) as c from delay_test", c, 1);
> +  inc $elapsed;
> +  dec $time_remaining;
> +
> +  if (!$time_remaining)
> +  {
> +    echo $row_count, $t, $time_remaining;

Where $t comes from? Should it be $elapsed?

> +    exit;
> +    die "Replication delay test got out of hand.  Aborting.";

Strange that die is after exit. Is it correct? Perhaps exit is only to close
server connections?

> +  }
> +}
> +select c1 from delay_test order by c1;
> +
> +# If the elapsed time is shorter than the delay, then the delay didn't work.
> +if (`select $elapsed < $delay`)
> +{
> +  echo $row_count, $t, $time_remaining;

$t again...

> +  echo "Failed!  Statement showed up on master before delay had elapsed.";
> +}
> +
> +# Clean up.
> +stop slave;
> +connection slave;
> +eval change master to master_delay=0;
> +start slave;
> +connection master;
> +drop table delay_test;
> +
> +##
> +
> +
> +# Other tests that may be a good idea:  Prove that one can:
> +# - Delay, stop the master, after delay elapsed start the master.
> +# - Delay, reduce the delay.
> +# - Delay, increase the delay.
> +# - Delay, remove the delay.
> +# - Replicate in a circle with a delay on one node.
> +# - Replicate in a circle with a delay on both nodes.
> diff -Nrup a/sql/lex.h b/sql/lex.h

> --- a/sql/lex.h	2007-07-12 05:15:31 -04:00
> +++ b/sql/lex.h	2007-09-10 18:28:30 -04:00
> @@ -300,6 +300,7 @@ static SYMBOL symbols[] = {
>    { "LOW_PRIORITY",	SYM(LOW_PRIORITY)},
>    { "MASTER",           SYM(MASTER_SYM)},
>    { "MASTER_CONNECT_RETRY",           SYM(MASTER_CONNECT_RETRY_SYM)},
> +  { "MASTER_DELAY",           SYM(MASTER_DELAY_SYM)},
>    { "MASTER_HOST",           SYM(MASTER_HOST_SYM)},
>    { "MASTER_LOG_FILE",           SYM(MASTER_LOG_FILE_SYM)},
>    { "MASTER_LOG_POS",           SYM(MASTER_LOG_POS_SYM)},

> diff -Nrup a/sql/rpl_mi.cc b/sql/rpl_mi.cc
> --- a/sql/rpl_mi.cc	2007-06-30 14:13:26 -04:00
> +++ b/sql/rpl_mi.cc	2007-09-10 18:28:30 -04:00
> @@ -30,7 +30,7 @@ int init_strvar_from_file(char *var, int
>  
>  MASTER_INFO::MASTER_INFO()
>    :Slave_reporting_capability("I/O"),
> -   ssl(0), fd(-1),  io_thd(0), port(MYSQL_PORT),
> +   ssl(0), fd(-1),  io_thd(0), port(MYSQL_PORT), delay(0),
>     connect_retry(DEFAULT_CONNECT_RETRY), inited(0), abort_slave(0),
>     slave_running(0),  ssl_verify_server_cert(0), slave_run_id(0)
>  {
> @@ -72,8 +72,11 @@ enum {
>    /* 5.1.16 added value of master_ssl_verify_server_cert */
>    LINE_FOR_MASTER_SSL_VERIFY_SERVER_CERT= 15,
>  
> +  /* added value of master delay */
> +  LINE_FOR_MASTER_DELAY= 16,
> +
>    /* Number of lines currently used when saving master info file */
> -  LINES_IN_MASTER_INFO= LINE_FOR_MASTER_SSL_VERIFY_SERVER_CERT
> +  LINES_IN_MASTER_INFO= LINE_FOR_MASTER_DELAY
>  };
>
>  
> @@ -176,6 +179,7 @@ file '%s')", fname);
>      mi->fd = fd;
>      int port, connect_retry, master_log_pos, lines;
>      int ssl= 0, ssl_verify_server_cert= 0;
> +    int delay= 0;
>      char *first_non_digit;
>  
>      /*
> @@ -258,6 +262,10 @@ file '%s')", fname);
>            init_intvar_from_file(&ssl_verify_server_cert, &mi->file, 0))
>          goto errwithmsg;
>  
> +      if (lines >= LINE_FOR_MASTER_DELAY &&
> +          init_intvar_from_file(&delay, &mi->file, 0))
> +        goto errwithmsg;
> +
>      }
>  
>  #ifndef HAVE_OPENSSL
> @@ -276,6 +284,7 @@ file '%s')", fname);
>      mi->connect_retry= (uint) connect_retry;
>      mi->ssl= (my_bool) ssl;
>      mi->ssl_verify_server_cert= ssl_verify_server_cert;
> +    mi->delay= (uint32) delay;
>    }
>    DBUG_PRINT("master_info",("log_file_name: %s  position: %ld",
>                              mi->master_log_name,
> @@ -357,13 +366,14 @@ int flush_master_info(MASTER_INFO* mi, b
>  
>    my_b_seek(file, 0L);
>    my_b_printf(file,
> -              "%u\n%s\n%s\n%s\n%s\n%s\n%d\n%d\n%d\n%s\n%s\n%s\n%s\n%s\n%d\n",
> +              "%u\n%s\n%s\n%s\n%s\n%s\n%d\n%d\n%d\n%s\n%s\n%s\n%s\n%s\n%d\n%u\n",
>                LINES_IN_MASTER_INFO,
>                mi->master_log_name, llstr(mi->master_log_pos, lbuf),
>                mi->host, mi->user,
>                mi->password, mi->port, mi->connect_retry,
>                (int)(mi->ssl), mi->ssl_ca, mi->ssl_capath, mi->ssl_cert,
> -              mi->ssl_cipher, mi->ssl_key, mi->ssl_verify_server_cert);
> +              mi->ssl_cipher, mi->ssl_key, mi->ssl_verify_server_cert,
> +              mi->delay);
>    DBUG_RETURN(-flush_io_cache(file));
>  }
>  

> diff -Nrup a/sql/rpl_mi.h b/sql/rpl_mi.h
> --- a/sql/rpl_mi.h	2007-06-30 13:43:52 -04:00
> +++ b/sql/rpl_mi.h	2007-09-10 18:28:30 -04:00
> @@ -100,6 +100,8 @@ class MASTER_INFO : public Slave_reporti
>  
>    */
>    long clock_diff_with_master;
> +  uint32 delay;                  ///< Replication delay, in seconds
> +
>  };
>  
>  void init_master_log_pos(MASTER_INFO* mi);

> diff -Nrup a/sql/slave.cc b/sql/slave.cc
> --- a/sql/slave.cc	2007-07-21 00:21:22 -04:00
> +++ b/sql/slave.cc	2007-09-10 18:28:30 -04:00
> @@ -1080,6 +1080,7 @@ bool show_master_info(THD* thd, MASTER_I
>    field_list.push_back(new Item_empty_string("Last_IO_Error", 20));
>    field_list.push_back(new Item_return_int("Last_SQL_Errno", 4, MYSQL_TYPE_LONG));
>    field_list.push_back(new Item_empty_string("Last_SQL_Error", 20));
> +  field_list.push_back(new Item_return_int("Delay", 10, MYSQL_TYPE_LONG));
>  
>    if (protocol->send_fields(&field_list,
>                              Protocol::SEND_NUM_ROWS | Protocol::SEND_EOF))
> @@ -1199,6 +1200,8 @@ bool show_master_info(THD* thd, MASTER_I
>      // Last_SQL_Error
>      protocol->store(mi->rli.last_error().message, &my_charset_bin);
>  
> +    protocol->store(mi->delay);
> +
>      pthread_mutex_unlock(&mi->rli.data_lock);
>      pthread_mutex_unlock(&mi->data_lock);
>  
> @@ -1586,7 +1589,37 @@ static int exec_relay_log_event(THD* thd
>        --rli->slave_skip_counter;
>      pthread_mutex_unlock(&rli->data_lock);
>      if (reason == Log_event::EVENT_SKIP_NOT)
> +    {
> +      time_t now;
> +      (void) time(&now);
> +      DBUG_PRINT("info", ("ev->when= %lu  now= %lu  delay= %lu  event= %s",
> +                          ev->when, now, rli->mi->delay,
> ev->get_type_str()));
> +      if ((rli->mi->delay != 0) &&
> +          (ev->get_type_code() != ROTATE_EVENT) &&
> +          ((now - ev->when) < (signed) rli->mi->delay))

I don't think it is crucial, but it would be more correct to read the delay
value under data_lock (above), when we know that it is not changing.

> +      {
> +        DBUG_PRINT("info", ("delaying replication event %s %lu secs",
> +                            ev->get_type_str(), 
> +                            rli->mi->delay - (now - ev->when)));
> +
> +        THD_SET_PROC_INFO(thd, "Sleeping until master-delay expires");

I think proc_info should be reset to the original value after the sleep.

> +        /*
> +          Here, this thread stops for a while.  That means that it doesn't
> +          matter if something interesting happens to the replication configur-
> +          ation, we can't know about it until this delay has expired or the
> +          slave is stopped (which also terminates this delay).  A smarter way
> +          probably is to delay for a scant moment and then jump back up a few
> +          levels and re-process configuration info (and perhaps peek ahead to
> +          future events) before rethinking whether to continue delaying.  Other
> +          code around here makes the same assumption, (c.f. ER_SLAVE_MUST_STOP)
> +          but this delay is more egregious than the rest.  Questions--ask Chad.
> +        */

I don't think we should worry about configuration changes. Here, we just use the
last delay value we have read from mi. If it changes during the sleep, the new
value will be effective when executing next event.

> +        safe_sleep(thd, rli->mi->delay - (now - ev->when),
> +                   (CHECK_KILLED_FUNC) sql_slave_killed,
> +                   (void*) rli);

What happens if thread is terminated during the wait? Perhaps we should check it
here and abort if it has happened. Something like this:

pthread_mutex_lock(&rli->data_lock);
if (sql_slave_killed(thd,rli))
{
   pthread_mutex_unlock(&rli->data_lock);
   delete ev;
   DBUG_RETURN(?);
}
pthread_mutex_unlock(&rli->data_lock);

> +      }
>        exec_res= ev->apply_event(rli);
> +    }
>  #ifndef DBUG_OFF
>      /*
>        This only prints information to the debug trace.

> diff -Nrup a/sql/sql_lex.h b/sql/sql_lex.h
> --- a/sql/sql_lex.h	2007-07-17 19:46:19 -04:00
> +++ b/sql/sql_lex.h	2007-09-10 18:28:30 -04:00
> @@ -188,6 +188,7 @@ typedef struct st_lex_master_info
>  {
>    char *host, *user, *password, *log_file_name;
>    uint port, connect_retry;
> +  uint32 delay;
>    ulonglong pos;
>    ulong server_id;
>    /*

> diff -Nrup a/sql/sql_repl.cc b/sql/sql_repl.cc
> --- a/sql/sql_repl.cc	2007-07-15 12:58:38 -04:00
> +++ b/sql/sql_repl.cc	2007-09-10 18:28:30 -04:00
> @@ -1124,6 +1124,8 @@ bool change_master(THD* thd, MASTER_INFO
>      mi->port = lex_mi->port;
>    if (lex_mi->connect_retry)
>      mi->connect_retry = lex_mi->connect_retry;
> +  if (lex_mi->delay)
> +    mi->delay= lex_mi->delay;
>  
>    if (lex_mi->ssl != LEX_MASTER_INFO::SSL_UNCHANGED)
>      mi->ssl= (lex_mi->ssl == LEX_MASTER_INFO::SSL_ENABLE);

> diff -Nrup a/sql/sql_yacc.yy b/sql/sql_yacc.yy
> --- a/sql/sql_yacc.yy	2007-07-18 03:41:19 -04:00
> +++ b/sql/sql_yacc.yy	2007-09-10 18:28:30 -04:00
> @@ -773,6 +773,7 @@ bool my_yyoverflow(short **a, YYSTYPE **
>  %token  LOW_PRIORITY
>  %token  LT                            /* OPERATOR */
>  %token  MASTER_CONNECT_RETRY_SYM
> +%token  MASTER_DELAY_SYM
>  %token  MASTER_HOST_SYM
>  %token  MASTER_LOG_FILE_SYM
>  %token  MASTER_LOG_POS_SYM
> @@ -1512,6 +1513,11 @@ master_def:
>         {
>  	 Lex->mi.connect_retry = $3;
>         }
> +       |
> +       MASTER_DELAY_SYM EQ ulong_num
> +       {
> +         Lex->mi.delay = $3;
> +       }

I wonder if there are some rules for parsing values of type TIME and whether
they should be used here to parse the value of MASTER_DELAY.

>         | MASTER_SSL_SYM EQ ulong_num
>           {
>             Lex->mi.ssl= $3 ? 
> @@ -10078,6 +10084,7 @@ keyword_sp:
>  	| MASTER_PASSWORD_SYM	{}
>  	| MASTER_SERVER_ID_SYM  {}
>  	| MASTER_CONNECT_RETRY_SYM	{}
> +	| MASTER_DELAY_SYM	{}
>  	| MASTER_SSL_SYM	{}
>  	| MASTER_SSL_CA_SYM	{}
>  	| MASTER_SSL_CAPATH_SYM	{}
>