List:Commits« Previous MessageNext Message »
From:Luis Soares Date:April 15 2010 4:39pm
Subject:bzr commit into mysql-5.1-rep+2 branch (luis.soares:3183) Bug#52166
View as plain text  
#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;
       }
       /*


Attachment: [text/bzr-bundle] bzr/luis.soares@sun.com-20100415163931-laujmcehk2pwirnk.bundle
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