MySQL Lists are EOL. Please join:

List:Commits« Previous MessageNext Message »
From:Sven Sandberg Date:April 28 2010 11:05am
Subject:Re: bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166
View as plain text  
Hi Luís,

Great work with this! Source patch is almost perfect (except it should 
set the timestamp to the event *end* time as discussed earlier). This is 
a nice simplification and it's great to get rid of some code.

Some requested changes in the test case:

  (R1) Please add comments to the test case that explain what properties 
are being tested and how they are being tested. Please see comments inline.

  (R2) I think the races can be removed completely from the test: please 
see comments inline.

  (R3) Minor simplifications, see comments inline.

  (R4) Please source include/show_rpl_debug_info.inc before die

/Sven


Luis Soares wrote:
> #At file:///home/lsoares/Workspace/bzr/work/bugfixing/52166/mysql-5.1-rep%2B2/ based
> on revid:zhenxing.he@stripped
> 
>  3183 Luis Soares	2010-04-15
>       BUG#52166: Seconds_Behind_Master spikes after long idle period
>       
>       Introduction: seconds behind master is calculated by checking the
>       time difference between the current time on the slave (time(0))
>       and the creation timestamp, at the master, of the last executed
>       event by the SQL thread. The last event timestamp is saved by the
>       SQL thread in rli->last_master_timestamp. Different timezones for
>       master and slave are taken into account when showing this
>       delta. The rli->last_master_timestamp is updated when the SQL
>       thread finishes the event execution at the slave.
>       
>       Problem: when the SQL thread has no events to replay in the relay
>       log, it waits. Right before waiting, it saves the last
>       event (lets call it e1) timestamp (rli->last_master_timestamp)
>       set at the master (in save_last_master_timestamp), and sets
>       rli->last_master_timestamp to zero. This makes 'SHOW SLAVE
>       STATUS' show zero while the SQL thread is waiting. However, when
>       the SQL thread awakes, most likely because of the fact that a new
>       event was enqueued in the relay log, it restores the
>       save_last_master_timestamp to rli->last_master_timestamp. Then it
>       goes on to process the new event (lets name it e2). Given this
>       and the fact that the SQL thread only updates the
>       rli->last_master_timestamp at the end of execution, there is a
>       time window that the user can notice a sudden spike on
>       Seconds_Behind_Master, especially if e2 arrives a long time after
>       e1 finished. The spike is actually enforced - value increases -
>       during e2 execution time, which means that if e2 execution
>       latency increases, then the likelihood that the user sees this
>       also increases.
>       
>       Solution: We fix this by not saving and restoring the
>       last_master_timestamp when the SQL thread goes to sleep. Instead,
>       we set the rli->last_master_timestamp to zero, when the SQL
>       thread starts waiting, and keep it to zero, when the SQL thread
>       awakes. A complementary change in this patch, is the one that
>       sets rli->last_master_timestamp before and not after event
>       execution. Both of these changes make the spike go away, and keep
>       showing zero, until the event starts being processed, as opposed
>       to showing zero until the event finishes its execution.
>      @ mysql-test/suite/manual/t/rpl_replication_delay.test
>         Removed this unmaintained test case.
>      @ mysql-test/suite/rpl/t/seconds_behind_master.test
>         Added some new tests. Collected remains from the removed 
>         rpl_replication_delay, refactored and added in this file as well.
>      @ sql/log_event.cc
>         Reworked the fault injection to meet the new test case needs.
>         Refactored the stmt_done interface (does not need 'when' anymore.
>      @ sql/log_event_old.cc
>         Accomodating changes in the stmt_done interface.
>      @ sql/rpl_rli.cc
>         Updated stmt_done implementation.
>      @ sql/rpl_rli.h
>         Changed stmt_done interface, removing the not needed 
>         event_creation_time.
>      @ sql/slave.cc
>         Two changes: 
>           (i) removed the save and restore of rli->last_master_timestamp, 
>               when the SQL thread goes to sleeps. 
>          (ii) Updating the rli->last_master_timestamp at the beginning of
>               the event execution.
> 
>     removed:
>       mysql-test/suite/manual/
>       mysql-test/suite/manual/r/
>       mysql-test/suite/manual/r/rpl_replication_delay.result
>       mysql-test/suite/manual/t/
>       mysql-test/suite/manual/t/rpl_replication_delay-slave.opt
>       mysql-test/suite/manual/t/rpl_replication_delay.test
>     added:
>       mysql-test/suite/rpl/r/seconds_behind_master.result
>       mysql-test/suite/rpl/t/seconds_behind_master.test
>     modified:
>       sql/log_event.cc
>       sql/log_event_old.cc
>       sql/rpl_rli.cc
>       sql/rpl_rli.h
>       sql/slave.cc
> === removed directory 'mysql-test/suite/manual'
> === removed directory 'mysql-test/suite/manual/r'
> === removed file 'mysql-test/suite/manual/r/rpl_replication_delay.result'
> --- a/mysql-test/suite/manual/r/rpl_replication_delay.result	2007-10-13 20:12:50
> +0000
> +++ b/mysql-test/suite/manual/r/rpl_replication_delay.result	1970-01-01 00:00:00
> +0000
> @@ -1,136 +0,0 @@
> -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;
> -show slave status /* Second_behind reports 0 */;;
> -Slave_IO_State	#
> -Master_Host	127.0.0.1
> -Master_User	root
> -Master_Port	9306
> -Connect_Retry	1
> -Master_Log_File	master-bin.000001
> -Read_Master_Log_Pos	106
> -Relay_Log_File	#
> -Relay_Log_Pos	#
> -Relay_Master_Log_File	master-bin.000001
> -Slave_IO_Running	Yes
> -Slave_SQL_Running	Yes
> -Replicate_Do_DB	
> -Replicate_Ignore_DB	
> -Replicate_Do_Table	
> -Replicate_Ignore_Table	
> -Replicate_Wild_Do_Table	
> -Replicate_Wild_Ignore_Table	
> -Last_Errno	0
> -Last_Error	
> -Skip_Counter	0
> -Exec_Master_Log_Pos	106
> -Relay_Log_Space	#
> -Until_Condition	None
> -Until_Log_File	
> -Until_Log_Pos	0
> -Master_SSL_Allowed	No
> -Master_SSL_CA_File	
> -Master_SSL_CA_Path	
> -Master_SSL_Cert	
> -Master_SSL_Cipher	
> -Master_SSL_Key	
> -Seconds_Behind_Master	0
> -Master_SSL_Verify_Server_Cert	No
> -Last_IO_Errno	0
> -Last_IO_Error	
> -Last_SQL_Errno	0
> -Last_SQL_Error	
> -drop table if exists t1;
> -Warnings:
> -Note	1051	Unknown table 't1'
> -create table t1 (f1 int);
> -flush logs /* contaminate rli->last_master_timestamp */;
> -lock table t1 write;
> -insert into t1 values (1);
> -show slave status /* bug emulated: reports slave threads starting time about 3*3 not
> 3 secs */;;
> -Slave_IO_State	#
> -Master_Host	127.0.0.1
> -Master_User	root
> -Master_Port	9306
> -Connect_Retry	1
> -Master_Log_File	master-bin.000001
> -Read_Master_Log_Pos	367
> -Relay_Log_File	#
> -Relay_Log_Pos	#
> -Relay_Master_Log_File	master-bin.000001
> -Slave_IO_Running	Yes
> -Slave_SQL_Running	Yes
> -Replicate_Do_DB	
> -Replicate_Ignore_DB	
> -Replicate_Do_Table	
> -Replicate_Ignore_Table	
> -Replicate_Wild_Do_Table	
> -Replicate_Wild_Ignore_Table	
> -Last_Errno	0
> -Last_Error	
> -Skip_Counter	0
> -Exec_Master_Log_Pos	279
> -Relay_Log_Space	#
> -Until_Condition	None
> -Until_Log_File	
> -Until_Log_Pos	0
> -Master_SSL_Allowed	No
> -Master_SSL_CA_File	
> -Master_SSL_CA_Path	
> -Master_SSL_Cert	
> -Master_SSL_Cipher	
> -Master_SSL_Key	
> -Seconds_Behind_Master	9
> -Master_SSL_Verify_Server_Cert	No
> -Last_IO_Errno	0
> -Last_IO_Error	
> -Last_SQL_Errno	0
> -Last_SQL_Error	
> -unlock tables;
> -flush logs /* this time rli->last_master_timestamp is not affected */;
> -lock table t1 write;
> -insert into t1 values (2);
> -show slave status /* reports the correct diff with master query time about 3+3 secs
> */;;
> -Slave_IO_State	#
> -Master_Host	127.0.0.1
> -Master_User	root
> -Master_Port	9306
> -Connect_Retry	1
> -Master_Log_File	master-bin.000001
> -Read_Master_Log_Pos	455
> -Relay_Log_File	#
> -Relay_Log_Pos	#
> -Relay_Master_Log_File	master-bin.000001
> -Slave_IO_Running	Yes
> -Slave_SQL_Running	Yes
> -Replicate_Do_DB	
> -Replicate_Ignore_DB	
> -Replicate_Do_Table	
> -Replicate_Ignore_Table	
> -Replicate_Wild_Do_Table	
> -Replicate_Wild_Ignore_Table	
> -Last_Errno	0
> -Last_Error	
> -Skip_Counter	0
> -Exec_Master_Log_Pos	367
> -Relay_Log_Space	#
> -Until_Condition	None
> -Until_Log_File	
> -Until_Log_Pos	0
> -Master_SSL_Allowed	No
> -Master_SSL_CA_File	
> -Master_SSL_CA_Path	
> -Master_SSL_Cert	
> -Master_SSL_Cipher	
> -Master_SSL_Key	
> -Seconds_Behind_Master	7
> -Master_SSL_Verify_Server_Cert	No
> -Last_IO_Errno	0
> -Last_IO_Error	
> -Last_SQL_Errno	0
> -Last_SQL_Error	
> -unlock tables;
> -drop table t1;
> 
> === removed directory 'mysql-test/suite/manual/t'
> === removed file 'mysql-test/suite/manual/t/rpl_replication_delay-slave.opt'
> --- a/mysql-test/suite/manual/t/rpl_replication_delay-slave.opt	2007-10-04 15:46:31
> +0000
> +++ b/mysql-test/suite/manual/t/rpl_replication_delay-slave.opt	1970-01-01 00:00:00
> +0000
> @@ -1 +0,0 @@
> ---loose-debug=d,let_first_flush_log_change_timestamp
> 
> === removed file 'mysql-test/suite/manual/t/rpl_replication_delay.test'
> --- a/mysql-test/suite/manual/t/rpl_replication_delay.test	2007-10-04 15:46:31 +0000
> +++ b/mysql-test/suite/manual/t/rpl_replication_delay.test	1970-01-01 00:00:00 +0000
> @@ -1,71 +0,0 @@
> -#
> -# Testing replication delay reporting (bug#29309)
> -# there is an unavoidable non-determinism in the test
> -# please compare the results with the comments 
> -#
> -
> -
> -source include/master-slave.inc;
> -
> -connection master;
> -#connection slave;
> -sync_slave_with_master;
> ---replace_result $DEFAULT_MASTER_PORT DEFAULT_MASTER_PORT
> ---replace_column 1 # 8 # 9 # 23 #
> ---query_vertical show slave status /* Second_behind reports 0 */;
> -sleep 3;
> -
> -### bug emulation
> -
> -connection master;
> -drop table if exists t1;
> -create table t1 (f1 int);
> -sleep 3;
> -
> -#connection slave;
> -sync_slave_with_master;
> -flush logs /* contaminate rli->last_master_timestamp */;
> -
> -connection slave;
> -lock table t1 write;
> -
> -connection master;
> -insert into t1 values (1);
> -
> -sleep 3;
> -
> -connection slave;
> ---replace_result $DEFAULT_MASTER_PORT DEFAULT_MASTER_PORT
> ---replace_column 1 # 8 # 9 # 23 #
> ---query_vertical show slave status /* bug emulated: reports slave threads starting
> time about 3*3 not 3 secs */;
> -unlock tables;
> -
> -connection master;
> -sync_slave_with_master;
> -
> -### bugfix
> -
> -
> -connection slave;
> -flush logs /* this time rli->last_master_timestamp is not affected */;
> -lock table t1 write;
> -
> -connection master;
> -insert into t1 values (2);
> -sleep 3;
> -
> -connection slave;
> ---replace_result $DEFAULT_MASTER_PORT DEFAULT_MASTER_PORT
> ---replace_column 1 # 8 # 9 # 23 #
> ---query_vertical show slave status /* reports the correct diff with master query
> time about 3+3 secs */;
> -unlock tables;
> -
> -connection master;
> -drop table t1;
> -
> -#connection slave;
> -sync_slave_with_master;
> -
> -
> -# End of tests
> -
> 
> === added file 'mysql-test/suite/rpl/r/seconds_behind_master.result'
> --- a/mysql-test/suite/rpl/r/seconds_behind_master.result	1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/r/seconds_behind_master.result	2010-04-15 16:39:31 +0000
> @@ -0,0 +1,33 @@
> +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;
> +SET @old_debug= @@global.debug;
> +call mtr.add_suppression('Unsafe statement binlogged in statement format since
> BINLOG_FORMAT = STATEMENT');
> +create table t1 (f1 int);
> +include/stop_slave.inc
> +insert into t1 values (1);
> +lock table t1 write;
> +include/start_slave.inc
> +unlock tables;
> +lock table t1 write;
> +insert into t1 values (2);
> +flush logs /* should not reset the sbm value */;
> +unlock tables;
> +drop table t1;
> +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;
> +SET GLOBAL DEBUG= '+d,dec_event_time_by_1_hour';
> +CREATE TABLE t1 (a INT);
> +SET GLOBAL DEBUG= '-d,dec_event_time_by_1_hour';
> +SET GLOBAL DEBUG= '+d,dec_event_time_by_1_hour';
> +INSERT INTO t1 VALUES (sleep (10));
> +SET GLOBAL DEBUG= '-d,dec_event_time_by_1_hour';
> +DROP TABLE t1;
> +SET @@global.debug= @old_debug;
> 
> === added file 'mysql-test/suite/rpl/t/seconds_behind_master.test'
> --- a/mysql-test/suite/rpl/t/seconds_behind_master.test	1970-01-01 00:00:00 +0000
> +++ b/mysql-test/suite/rpl/t/seconds_behind_master.test	2010-04-15 16:39:31 +0000
> @@ -0,0 +1,152 @@

(R1)

Please add comments summarizing what properties are being tested 
(purpose), and how they are being tested (implementation).

My impression is that the parts that you borrowed from 
rpl_replication_delay are very similar to the parts that you introduced. 
If there is a difference, it would be good to list the tested properties 
together so that it is clear that there are no redundant tests.

> +-- source include/master-slave.inc
> +-- source include/have_debug.inc
> +
> +# make the test only run once (STMT is actually needed because of the SLEEPs below)
> +-- source include/have_binlog_format_statement.inc 
> +
> +SET @old_debug= @@global.debug;
> +call mtr.add_suppression('Unsafe statement binlogged in statement format since
> BINLOG_FORMAT = STATEMENT');
> +
> +#
> +#  Based on BUG#29309 test case

(R1)

After you removed rpl_replication_delay, this actually *is* the 
BUG#29309 test case, you just rewrote it, right? If we say that test X 
is based on test Y, then I think test Y must exist (and be referred to 
in an explicit manner, like a filename); otherwise it will be very hard 
to figure out what is going on for someone who doesn't know the context.

Also, please explain what property is being tested here.

> +#
> +
> +connection master;
> +create table t1 (f1 int);
> +sync_slave_with_master;
> +source include/stop_slave.inc;
> +connection master;
> +insert into t1 values (1);
> +
> +sleep 3;
> +
> +#connection slave;

(R3) This line can be removed.

> +connection slave;
> +lock table t1 write;
> +source include/start_slave.inc;
> +
> +# ok, now wait for the SQL thread to start the insert
> +let $wait_timeout= 60; # Override default of 30 seconds with 60.
> +let $show_statement= SHOW PROCESSLIST;
> +let $field= Info;
> +let $condition= = 'insert into t1 values (1)';
> +source include/wait_show_condition.inc;
> +
> +let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
> +if (`SELECT $sbm < 3 or $sbm > 6`)
> +{
> +  -- echo #### Seconds behind master must show value approx. to 3
> +  -- echo #### giving a 3 secs margin (machine where the test executes
> +  -- echo #### may be slow). Best effort approach.
> +  -- echo #### $sbm > 6 || $sbm < 3

(R1) This paragraph doesn't parse well for me. Please try to restructure 
the text so that it is clear what property was being tested and failed.

(R4) Also, please source include/show_rpl_debug_info.inc before die.

(R2) Also, I think the test could be written without races: if you read 
UNIX_TIMESTAMP() before executing 'insert' on master, and read 
UNIX_TIMESTAMP() again after you read Seconds_Behind_Master, then the 
upper bound on $sbm is the difference between the two.

> +  -- die
> +}
> +
> +unlock tables;
> +connection master;
> +sync_slave_with_master;
> +lock table t1 write;
> +connection master;
> +insert into t1 values (2);
> +
> +sleep 3;
> +
> +connection slave;
> +# ok, now wait for the SQL thread to start the insert
> +let $wait_timeout= 60; # Override default of 30 seconds with 60.
> +let $show_statement= SHOW PROCESSLIST;
> +let $field= Info;
> +let $condition= = 'insert into t1 values (2)';
> +source include/wait_show_condition.inc;
> +
> +flush logs /* should not reset the sbm value */;
> +
> +sleep 3;
> +
> +let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
> +if (`SELECT $sbm < 6 or $sbm >= 9`)
> +{
> +  -- echo #### Seconds behind master must show value approx. to 6
> +  -- echo #### giving a 3 secs margin (machine where the test executes
> +  -- echo #### may be slow). Best effort approach.
> +  -- echo #### $sbm < 6 || $sbm >= 9 

(R1), (R4), (R2) Similar to above: please clarify what tested property 
failed to hold; source include/show_rpl_debug_info.inc before die; and 
consider using UNIX_TIMESTAMP() to remove races from the test.

> +  -- die
> +}
> +
> +unlock tables;
> +connection master;
> +drop table t1;
> +sync_slave_with_master;
> +
> +#
> +# BUG#52166 test case 
> +#
> +
> +#  1. Check that seconds behind master is set to 0 when SQL 
> +#     thread waits for more events.
> +#  2. Check that seconds behind master is updated once after 
> +#     a newly received event starts to be processed.
> +
> +-- source include/master-slave-reset.inc
> +-- connection master
> +
> +# this will increase the timestamp +3600
> +SET GLOBAL DEBUG= '+d,dec_event_time_by_1_hour';
> +CREATE TABLE t1 (a INT);
> +SET GLOBAL DEBUG= '-d,dec_event_time_by_1_hour';

(R3) Why are we altering the event's timestamp? This doesn't seem to be 
used. Suggest to remove this.

> +-- sync_slave_with_master
> +
> +# ok, now wait for the SQL thread to sleep
> +let $wait_timeout= 60; # Override default of 30 seconds with 60.
> +let $show_statement= SHOW PROCESSLIST;
> +let $field= State;
> +let $condition= = 'Slave has read all relay log; waiting for the slave I/O thread to
> update it';
> +-- source include/wait_show_condition.inc
> +
> +-- let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1)
> +if (`SELECT $sbm <> 0`)
> +{
> +  -- echo #### Seconds behind master must show '0', because SQL thread is now
> waiting for new events.
> +  -- echo #### SBM ($sbm seconds) != 0 !! SQL thread is waiting so should be zero.
> +  -- die
> +}
> +
> +-- connection master
> +
> +# 5 seconds this will give us time at the slave to 
> +# show that the Seconds_Behind_Master will increase
> +# when this query starts to execute

(R1) This sentence assumes that the reader already understands what is 
being tested. Please explain that! Also, the number 5 doesn't match the 
sleep of 10 seconds below.

> +-- disable_warnings
> +SET GLOBAL DEBUG= '+d,dec_event_time_by_1_hour';
> +INSERT INTO t1 VALUES (sleep (10));
> +SET GLOBAL DEBUG= '-d,dec_event_time_by_1_hour';

(R2) This test contains a race due to the sleep. I think we can use LOCK 
TABLES, as above, to get rid of the race. I.e.:

  slave> LOCK TABLES t1
master> INSERT INTO t1 VALUES(1); # with modified timestamp
  slave> wait_show_condition       # until INSERT shows up in processlist
  slave> query_get_value(SHOW SLAVE STATUS, Seconds_Behind_Master, 1)
etc.

> +DROP TABLE t1;

(R3) For clarity, I'd suggest to move this cleanup code until the end.

> +-- enable_warnings
> +
> +-- connection slave
> +
> +# ok, now wait for the SQL thread to start the insert
> +let $wait_timeout= 60; # Override default of 30 seconds with 60.
> +let $show_statement= SHOW PROCESSLIST;
> +let $field= Info;
> +let $condition= = 'INSERT INTO t1 VALUES (sleep (10))';
> +-- source include/wait_show_condition.inc
> +
> +-- sleep 2
> +
> +-- let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1)
> +if (`SELECT $sbm <= 3600`)
> +{
> +  -- echo #### Seconds behind master must show > 3600 because the event that 
> +  -- echo #### is being processed was issued 3600 seconds ago.
> +  -- echo #### SBM ($sbm seconds) <= 3600 ! 
> +  -- die
> +}
> +
> +-- connection master
> +-- sync_slave_with_master
> +-- connection master
> +
> +SET @@global.debug= @old_debug;
> +
> +-- source include/master-slave-end.inc
> 
> === modified file 'sql/log_event.cc'
> --- a/sql/log_event.cc	2010-03-03 14:43:35 +0000
> +++ b/sql/log_event.cc	2010-04-15 16:39:31 +0000
> @@ -235,10 +235,6 @@ private:
>    flag_set m_flags;
>  };
>  
> -#ifndef DBUG_OFF
> -uint debug_not_change_ts_if_art_event= 1; // bug#29309 simulation
> -#endif
> -
>  /*
>    pretty_print_str()
>  */
> @@ -781,32 +777,7 @@ int Log_event::do_update_pos(Relay_log_i
>      Matz: I don't think we will need this check with this refactoring.
>    */
>    if (rli)
> -  {
> -    /*
> -      bug#29309 simulation: resetting the flag to force
> -      wrong behaviour of artificial event to update
> -      rli->last_master_timestamp for only one time -
> -      the first FLUSH LOGS in the test.
> -    */
> -    DBUG_EXECUTE_IF("let_first_flush_log_change_timestamp",
> -                    if (debug_not_change_ts_if_art_event == 1
> -                        && is_artificial_event())
> -                    {
> -                      debug_not_change_ts_if_art_event= 0;
> -                    });
> -#ifndef DBUG_OFF
> -    rli->stmt_done(log_pos, 
> -                   is_artificial_event() &&
> -                   debug_not_change_ts_if_art_event > 0 ? 0 : when);
> -#else
> -    rli->stmt_done(log_pos, is_artificial_event()? 0 : when);
> -#endif
> -    DBUG_EXECUTE_IF("let_first_flush_log_change_timestamp",
> -                    if (debug_not_change_ts_if_art_event == 0)
> -                    {
> -                      debug_not_change_ts_if_art_event= 2;
> -                    });
> -  }
> +    rli->stmt_done(log_pos);
>    return 0;                                   // Cannot fail currently
>  }
>  
> @@ -942,6 +913,16 @@ bool Log_event::write_header(IO_CACHE* f
>    }
>  
>    now= (ulong) get_time();                              // Query start time
> +  if (DBUG_EVALUATE_IF("inc_event_time_by_1_hour",1,0)  &&
> +      DBUG_EVALUATE_IF("dec_event_time_by_1_hour",1,0))
> +  {
> +    DBUG_ASSERT(0);
> +  } 
> +  else
> +  {
> +    DBUG_EXECUTE_IF("inc_event_time_by_1_hour", now= now + 3600;);
> +    DBUG_EXECUTE_IF("dec_event_time_by_1_hour", now= now - 3600;);
> +  }
>  
>    /*
>      Header will be of size LOG_EVENT_HEADER_LEN for all events, except for
> @@ -7873,7 +7854,7 @@ Rows_log_event::do_update_pos(Relay_log_
>        Step the group log position if we are not in a transaction,
>        otherwise increase the event log position.
>      */
> -    rli->stmt_done(log_pos, when);
> +    rli->stmt_done(log_pos);
>      /*
>        Clear any errors in thd->net.last_err*. It is not known if this is
>        needed or not. It is believed that any errors that may exist in
> 
> === modified file 'sql/log_event_old.cc'
> --- a/sql/log_event_old.cc	2010-03-03 14:43:35 +0000
> +++ b/sql/log_event_old.cc	2010-04-15 16:39:31 +0000
> @@ -1889,7 +1889,7 @@ Old_rows_log_event::do_update_pos(Relay_
>        Step the group log position if we are not in a transaction,
>        otherwise increase the event log position.
>       */
> -    rli->stmt_done(log_pos, when);
> +    rli->stmt_done(log_pos);
>      /*
>        Clear any errors in thd->net.last_err*. It is not known if this is
>        needed or not. It is believed that any errors that may exist in
> 
> === modified file 'sql/rpl_rli.cc'
> --- a/sql/rpl_rli.cc	2010-02-12 23:30:44 +0000
> +++ b/sql/rpl_rli.cc	2010-04-15 16:39:31 +0000
> @@ -1137,12 +1137,8 @@ bool Relay_log_info::cached_charset_comp
>  }
>  
>  
> -void Relay_log_info::stmt_done(my_off_t event_master_log_pos,
> -                                  time_t event_creation_time)
> +void Relay_log_info::stmt_done(my_off_t event_master_log_pos)
>  {
> -#ifndef DBUG_OFF
> -  extern uint debug_not_change_ts_if_art_event;
> -#endif
>    clear_flag(IN_STMT);
>  
>    /*
> @@ -1174,20 +1170,6 @@ void Relay_log_info::stmt_done(my_off_t 
>    {
>      inc_group_relay_log_pos(event_master_log_pos);
>      flush_relay_log_info(this);
> -    /*
> -      Note that Rotate_log_event::do_apply_event() does not call this
> -      function, so there is no chance that a fake rotate event resets
> -      last_master_timestamp.  Note that we update without mutex
> -      (probably ok - except in some very rare cases, only consequence
> -      is that value may take some time to display in
> -      Seconds_Behind_Master - not critical).
> -    */
> -#ifndef DBUG_OFF
> -    if (!(event_creation_time == 0 && debug_not_change_ts_if_art_event >
> 0))
> -#else
> -      if (event_creation_time != 0)
> -#endif
> -        last_master_timestamp= event_creation_time;
>    }
>  }
>  
> 
> === modified file 'sql/rpl_rli.h'
> --- a/sql/rpl_rli.h	2010-02-12 23:30:44 +0000
> +++ b/sql/rpl_rli.h	2010-04-15 16:39:31 +0000
> @@ -381,14 +381,8 @@ public:
>      Master log position of the event. The position is recorded in the
>      relay log info and used to produce information for <code>SHOW
>      SLAVE STATUS</code>.
> -
> -    @param event_creation_time
> -    Timestamp for the creation of the event on the master side. The
> -    time stamp is recorded in the relay log info and used to compute
> -    the <code>Seconds_behind_master</code> field.
>    */
> -  void stmt_done(my_off_t event_log_pos,
> -                 time_t event_creation_time);
> +  void stmt_done(my_off_t event_log_pos);
>  
>  
>    /**
> 
> === modified file 'sql/slave.cc'
> --- a/sql/slave.cc	2010-02-12 23:30:44 +0000
> +++ b/sql/slave.cc	2010-04-15 16:39:31 +0000
> @@ -2373,6 +2373,18 @@ static int exec_relay_log_event(THD* thd
>    {
>      int exec_res;
>  
> +    /* 
> +      Even if we don't execute this event, we keep the master timestamp,
> +      so that seconds behind master shows correct delta (there are events
> +      that are not replayed, so we keep falling behind).
> +
> +      If it is an artificial event, or a relay log event (IO thread generated
> +      event) or ev->when is set to 0, we don't update the 
> +      last_master_timestamp.
> +     */
> +    if (!(ev->is_artificial_event() || ev->is_relay_log_event() ||
> (ev->when == 0)))
> +      rli->last_master_timestamp= ev->when;
> +
>      /*
>        This tests if the position of the beginning of the current event
>        hits the UNTIL barrier.
> @@ -4469,7 +4481,9 @@ static Log_event* next_event(Relay_log_i
>            waiting for the following event) reset whenever EOF is
>            reached.
>          */
> -        time_t save_timestamp= rli->last_master_timestamp;
> +
> +        /* shows zero while it is sleeping (and until the next event 
> +           is about to be executed) */
>          rli->last_master_timestamp= 0;
>  
>          DBUG_ASSERT(rli->relay_log.get_open_count() ==
> @@ -4539,7 +4553,6 @@ static Log_event* next_event(Relay_log_i
>          rli->relay_log.wait_for_update_relay_log(rli->sql_thd);
>          // re-acquire data lock since we released it earlier
>          pthread_mutex_lock(&rli->data_lock);
> -        rli->last_master_timestamp= save_timestamp;
>          continue;
>        }
>        /*
> 
> 
> 
> ------------------------------------------------------------------------
> 
> 


-- 
Sven Sandberg, Software Engineer
MySQL AB, www.mysql.com
Thread
bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166Luis Soares15 Apr
  • Re: bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166Sven Sandberg27 Apr
  • Re: bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166Sven Sandberg28 Apr
    • Re: bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166Luís Soares30 Apr
Re: bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166Luís Soares22 Apr