Hi Luís,
I haven't yet looked at the full patch, so this is only a partial review.
As we discussed on IRC ( http://tinyurl.com/29e2glx ), please set the
timestamp to the event's end time (ev->when + ev->exec_time) at the
beginning of next_event. I'll review more tomorrow :-)
/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 @@
> +-- 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
> +#
> +
> +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;
> +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
> + -- 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
> + -- 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';
> +-- 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
> +-- 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';
> +DROP TABLE t1;
> +-- 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
