MDEV-33856 Additions

 * Updated RESET SLAVE to reset Master/Slave_last_event_time

 * Updated SHOW ALL SLAVES STATUS to treat Master and Slave NULL
   times separately

 * Updated SQL thread's update on first transaction read-in to
   only update Slave_last_event_time on group events

 * Added test cases for
   - Ensuring (Master|Slave)_last_event_time is updated at the
     correct place
   - Ensuring the first event read by the SQL thread will update
     Slave_last_event_time
   - A parallel delayed replica updates the new fields
     correctly

mysql-test/suite/rpl/r/master_last_event_time.result

@@ -5,14 +5,79 @@ include/rpl_init.inc [topology=1->2->3]
 #
 connection server_1;
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
+include/save_master_pos.inc
 connection server_2;
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
 connection server_3;
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
+#
+# Test *_last_event_time is updated at proper place.
+# Master_last_event_time should be updated by the IO thread when reading
+# in a new transaction from the primary.
+# Slave_last_event_time should be updated by the SQL thread
+#   1) immediately upon seeing the first transaction if the replica is
+#      starting fresh, or
+#   2) after committing a transaction.
+#
 connection server_2;
+start slave io_thread;
+include/sync_io_with_master.inc
 master_time: NULL (should be NULL)
+slave_time: NULL (should be NULL)
+# Sleep 2s to create a time gap between the header events (i.e.
+# Format_description and Gtid_list) and the transaction event to allow
+# proving that header events should not update
+# (Master|Slave)_last_event_time
+connect  server_1_1,127.0.0.1,root,,test,$SERVER_MYPORT_1,;
+set @@timestamp= TIMESTAMP;
+insert into t1 values (0);
+include/save_master_pos.inc
+connection server_2;
+include/sync_io_with_master.inc
+# For the first event, at execution start, Slave_last_event_time should
+# be updated to be 1 second prior to the time that the first transaction
+# was binlogged on the primary. This is to represent that the slave is
+# otherwise up-to-date. Note the table is locked to prevent the
+# transaction from committing (and thereby progressing
+# Slave_last_event_time to represent commit-time).
+connect  server_2_2,127.0.0.1,root,,test,$SERVER_MYPORT_2,;
+lock tables t1 write;
+connection server_2;
+start slave sql_thread;
+# Waiting for replica to start executing the transaction (yet get stuck on the table lock)
+connection server_2_2;
+unlock tables;
+connection server_2;
+include/wait_for_slave_param.inc [Relay_Master_Log_File]
+include/wait_for_slave_param.inc [Exec_Master_Log_Pos]
+#
+# Test that changes are properly applied by server_2 and server_3
+#
+connection server_1;
+include/save_master_gtid.inc
+connection server_2;
+include/sync_with_master_gtid.inc
+# Show that the server_2 received the insert from master
+select * from t1;
+a
+0
+master <> NULL; Should be 1
+1
+master_time == slave_time ; Should be 1
+1
 connection server_3;
+include/start_slave.inc
+include/sync_with_master_gtid.inc
+# Show that the server_3 received the insert from master
+select * from t1;
+a
+0
+master <> NULL; Should be 1
+1
+master_time == slave_time ; Should be 1
+1
 include/stop_slave.inc
+connection server_1;
 #
 # Test simple insert
 #
@@ -21,12 +86,14 @@ insert into t1 values (1+sleep(3));
 #
 # Test that changes are properly applied by server_2 and server_3
 #
+connection server_1;
 include/save_master_gtid.inc
 connection server_2;
 include/sync_with_master_gtid.inc
 # Show that the server_2 received the insert from master
 select * from t1;
 a
+0
 1
 master <> NULL; Should be 1
 1
@@ -38,6 +105,7 @@ include/sync_with_master_gtid.inc
 # Show that the server_3 received the insert from master
 select * from t1;
 a
+0
 1
 master <> NULL; Should be 1
 1
@@ -53,12 +121,14 @@ insert into t1 values (2+sleep(3));
 #
 # Test that changes are properly applied by server_2 and server_3
 #
+connection server_1;
 include/save_master_gtid.inc
 connection server_2;
 include/sync_with_master_gtid.inc
 # Show that the server_2 received the insert from master
 select * from t1;
 a
+0
 1
 2
 master <> NULL; Should be 1
@@ -71,6 +141,7 @@ include/sync_with_master_gtid.inc
 # Show that the server_3 received the insert from master
 select * from t1;
 a
+0
 1
 2
 master <> NULL; Should be 1
@@ -89,12 +160,14 @@ commit;
 #
 # Test that changes are properly applied by server_2 and server_3
 #
+connection server_1;
 include/save_master_gtid.inc
 connection server_2;
 include/sync_with_master_gtid.inc
 # Show that the server_2 received the insert from master
 select * from t1;
 a
+0
 1
 2
 3
@@ -109,6 +182,7 @@ include/sync_with_master_gtid.inc
 # Show that the server_3 received the insert from master
 select * from t1;
 a
+0
 1
 2
 3

mysql-test/suite/rpl/r/rpl_parallel_sbm.result

@@ -23,6 +23,11 @@ connection slave;
 # Waiting for transaction to arrive on slave and begin SQL Delay..
 # Validating SBM is updated on event arrival..
 # ..done
+# MDEV-33856: New definition for Seconds_Behind_Master
+# Validating Master_last_event_time is updated on event arrival..
+# ..done
+# Validating Slave_last_event_time is still from the last transaction..
+# ..done
 # MDEV-32265. At time of STOP SLAVE, if the SQL Thread is currently
 # delaying a transaction; then when the reciprocal START SLAVE occurs,
 # if the event is still to be delayed, SBM should resume accordingly
@@ -41,6 +46,9 @@ connection slave;
 connection server_2;
 UNLOCK TABLES;
 include/sync_with_master_gtid.inc
+# MDEV-33856: New definition for Seconds_Behind_Master
+# Ensuring Slave_last_event_time is now up-to-date once event is executed
+# ..done
 #
 # Pt 2) If the worker threads have not entered an idle state, ensure
 # following events do not update SBM

mysql-test/suite/rpl/t/master_last_event_time.inc

@@ -2,6 +2,7 @@
 --echo # Test that changes are properly applied by server_2 and server_3
 --echo #
 
+--connection server_1
 --source include/save_master_gtid.inc
 
 --connection server_2

mysql-test/suite/rpl/t/master_last_event_time.test

 --source include/have_innodb.inc
 --source include/have_binlog_format_row.inc
+--let $rpl_skip_start_slave=1
 --let $rpl_topology=1->2->3
 --source include/rpl_init.inc
 
@@ -10,21 +11,125 @@
 
 --connection server_1
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
-save_master_pos;
+--source include/save_master_pos.inc
 --connection server_2
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
 --connection server_3
 SET STATEMENT sql_log_bin=0 FOR create table t1 (a int) engine=innodb;
 
-# Ensure Master_last_event_time is not yet set
+--echo #
+--echo # Test *_last_event_time is updated at proper place.
+--echo # Master_last_event_time should be updated by the IO thread when reading
+--echo # in a new transaction from the primary.
+--echo # Slave_last_event_time should be updated by the SQL thread
+--echo #   1) immediately upon seeing the first transaction if the replica is
+--echo #      starting fresh, or
+--echo #   2) after committing a transaction.
+--echo #
+
 --connection server_2
-sync_with_master;
+start slave io_thread;
+--source include/sync_io_with_master.inc
+
+# Ensure Master_last_event_time and Slave_last_event_time are not yet set
 --let $master_time= query_get_value(SHOW ALL SLAVES STATUS, Master_last_event_time, 1)
 --echo master_time: $master_time (should be NULL)
+--let $slave_time= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1)
+--echo slave_time: $slave_time (should be NULL)
+
+--echo # Sleep 2s to create a time gap between the header events (i.e.
+--echo # Format_description and Gtid_list) and the transaction event to allow
+--echo # proving that header events should not update
+--echo # (Master|Slave)_last_event_time
+--sleep 2
+
+--connect (server_1_1,127.0.0.1,root,,test,$SERVER_MYPORT_1,)
+--let $t1_time_begin= `select truncate(@@timestamp,0)`
+--replace_result $t1_time_begin TIMESTAMP
+--eval set @@timestamp= $t1_time_begin
+insert into t1 values (0);
+
+--source include/save_master_pos.inc
+
+--connection server_2
+--source include/sync_io_with_master.inc
+
+--let $mle_time= query_get_value(SHOW ALL SLAVES STATUS, Master_last_event_time, 1)
+--let $mle_time_unix= `select truncate(unix_timestamp("$mle_time"),0)`
+if (`SELECT ($mle_time_unix < $t1_time_begin)`)
+{
+  --echo # Expected timestamp (master binlog time): $t1_time_begin
+  --echo # Reported Master_last_event_time: $mle_time_unix ($mle_time)
+  --die Master_last_event_time did not correspond to time that the transaction was binlogged on primary
+}
+
+--let $slave_time= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1)
+if (`select strcmp("$slave_time", "NULL") != 0`)
+{
+  --echo # Slave_last_event_time: $slave_time
+  --die SQL thread was never started, Slave_last_event_time should be NULL
+}
+
+--let $time_diff= query_get_value(SHOW ALL SLAVES STATUS, Master_Slave_time_diff, 1)
+if (`select strcmp("$time_diff", "NULL") != 0`)
+{
+  --echo # Master_Slave_time_diff: $time_diff
+  --die SQL thread was never started, Master_Slave_time_diff should be NULL
+}
+
+--echo # For the first event, at execution start, Slave_last_event_time should
+--echo # be updated to be 1 second prior to the time that the first transaction
+--echo # was binlogged on the primary. This is to represent that the slave is
+--echo # otherwise up-to-date. Note the table is locked to prevent the
+--echo # transaction from committing (and thereby progressing
+--echo # Slave_last_event_time to represent commit-time).
+
+
+--connect (server_2_2,127.0.0.1,root,,test,$SERVER_MYPORT_2,)
+lock tables t1 write;
+
+--connection server_2
+start slave sql_thread;
+
+--echo # Waiting for replica to start executing the transaction (yet get stuck on the table lock)
+--let $wait_condition= SELECT count(*) FROM information_schema.processlist WHERE state LIKE 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+
+--let $slave_time= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1)
+--let $slave_time_unix= `select truncate(unix_timestamp("$slave_time"),0)`
+--let $expected_slave_time= `select ($t1_time_begin - 1)`
+if ($slave_time_unix != $expected_slave_time)
+{
+  --echo # Master_last_event_time: $mle_time_unix ($mle_time)
+  --echo # Slave_last_event_time: $slave_time_unix ($slave_time)
+  --echo # Expected value: $expected_slave_time
+  --die SQL thread has not yet committed its first transaction, Slave_last_event_time should be 1s before that transaction
+}
+
+# Master_Slave_time_diff isn't guaranteed to be 1 second, despite the
+# hard-coded logic to subtract 1s from the first non-group event that comes in.
+# This is because the Gtid and Xid events can be logged with different
+# timestamps, and Slave_last_event_time is updated using the Gtid log event,
+# and Master_last_event_time is updated using the Xid log event. So to ensure
+# that Master_Slave_time_diff is updated correctly for the first transaction,
+# it must also take into account the difference in timestamps of these events
+--let $xid_gtid_time_diff=`SELECT $mle_time_unix - $t1_time_begin`
+--let $time_diff= query_get_value(SHOW ALL SLAVES STATUS, Master_Slave_time_diff, 1)
+if (`SELECT $time_diff != 1 + $xid_gtid_time_diff`)
+{
+  --echo # Master_Slave_time_diff: $time_diff
+  --echo # Xid Gtid Timestamp Difference: $xid_gtid_time_diff
+  --die SQL thread has not yet committed its first transaction, Master_Slave_time_diff should be updated to look up-to-date prior to this trx
+}
+
+--connection server_2_2
+unlock tables;
+
+--connection server_2
+--source include/sync_with_master.inc
+--source master_last_event_time.inc
+
 
-# Stop server_3 to check that it catches up gracefully
---connection server_3
---source include/stop_slave.inc
 
 --echo #
 --echo # Test simple insert

mysql-test/suite/rpl/t/rpl_parallel_sbm.test

@@ -61,6 +61,30 @@ if (`SELECT $sbm_trx1_arrive > ($seconds_since_idling + 1)`)
 }
 --echo # ..done
 
+--echo # MDEV-33856: New definition for Seconds_Behind_Master
+--echo # Validating Master_last_event_time is updated on event arrival..
+--let $mle_time_trx1_arrive= query_get_value(SHOW ALL SLAVES STATUS, Master_last_event_time, 1)
+--let $mle_time_trx1_arrive_unix= `SELECT truncate(unix_timestamp("$mle_time_trx1_arrive"), 0)`
+if (`SELECT $mle_time_trx1_arrive_unix < ($ts_trx_before_ins - 1)`)
+{
+    --echo # Master_last_event_time: $mle_time_trx1_arrive_unix ($mle_time_trx1_arrive)
+    --die Master_last_event_time was not updated for delayed replica at event arrival time
+}
+--echo # ..done
+
+--echo # Validating Slave_last_event_time is still from the last transaction..
+# Note we infer Slave_last_event_time via Master_Slave_time_diff
+--let $time_diff_trx1_arrive= query_get_value(SHOW ALL SLAVES STATUS, Master_Slave_time_diff, 1)
+if ($time_diff_trx1_arrive < 5)
+{
+    --let $slave_time_trx1_arrive= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1)
+    --let $slave_time_trx1_arrive_unix= `SELECT truncate(unix_timestamp("$slave_time_trx1_arrive"), 0)`
+    --echo # Slave_last_event_time: $slave_time_trx1_arrive_unix ($slave_time_trx1_arrive)
+    --echo # Master_Slave_time_diff: $time_diff_trx1_arrive
+    --die Slave_last_event_time is too recent, should not be less than 5 seconds, ie. 3 from delay + 2 from sleep
+}
+--echo # ..done
+
 
 --echo # MDEV-32265. At time of STOP SLAVE, if the SQL Thread is currently
 --echo # delaying a transaction; then when the reciprocal START SLAVE occurs,
@@ -98,6 +122,24 @@ UNLOCK TABLES;
 
 --source include/sync_with_master_gtid.inc
 
+--echo # MDEV-33856: New definition for Seconds_Behind_Master
+--echo # Ensuring Slave_last_event_time is now up-to-date once event is executed
+--let $slave_time_trx1_commit= query_get_value(SHOW ALL SLAVES STATUS, Slave_last_event_time, 1)
+--let $slave_time_trx1_commit_unix= `SELECT truncate(unix_timestamp("$slave_time_trx1_commit"),0)`
+if ($slave_time_trx1_commit_unix != $mle_time_trx1_arrive_unix)
+{
+    --echo # Slave_last_event_time: $slave_time_trx1_commit_unix ($slave_time_trx1_commit)
+    --echo # Master_last_event_time: $mle_time_trx1_arrive_unix ($mle_time_trx1_arrive)
+    --die Slave_last_event_time is not equal to Master_last_event_time despite being up-to-date
+}
+--let $time_diff_trx1_commit= query_get_value(SHOW ALL SLAVES STATUS, Master_Slave_time_diff, 1)
+if ($time_diff_trx1_commit != 0)
+{
+    --echo # Master_Slave_time_diff: $time_diff_trx1_commit
+    --die Master_Slave_time_diff should be 0, as slave is up-to-date
+}
+--echo # ..done
+
 --echo #
 --echo # Pt 2) If the worker threads have not entered an idle state, ensure
 --echo # following events do not update SBM

sql/slave.cc

@@ -3391,17 +3391,27 @@ static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full,
 
     if (full)
     {
+      MYSQL_TIME time;
       protocol->store((uint32)    mi->rli.retried_trans);
       protocol->store((ulonglong) mi->rli.max_relay_log_size);
       protocol->store(mi->rli.executed_entries);
       protocol->store((uint32)    mi->received_heartbeats);
       protocol->store_double(mi->heartbeat_period, 3);
       protocol->store(gtid_pos->ptr(), gtid_pos->length(), &my_charset_bin);
+
       if (mi->rli.newest_master_timestamp)
       {
-        MYSQL_TIME time;
         timestamp_to_my_time(&time, mi->rli.newest_master_timestamp);
         protocol->store_datetime(&time, 0);
+      }
+      else
+      {
+        protocol->store_null();
+      }
+
+      if (mi->rli.slave_timestamp)
+      {
+        DBUG_ASSERT(mi->rli.newest_master_timestamp);
         timestamp_to_my_time(&time, mi->rli.slave_timestamp);
         protocol->store_datetime(&time, 0);
         protocol->store((uint32) (mi->rli.newest_master_timestamp -
@@ -3411,7 +3421,6 @@ static bool send_show_master_info_data(THD *thd, Master_info *mi, bool full,
       {
         protocol->store_null();
         protocol->store_null();
-        protocol->store_null();
       }
     }
     mysql_mutex_unlock(&mi->rli.err_lock);
@@ -4310,7 +4319,8 @@ static int exec_relay_log_event(THD* thd, Relay_log_info* rli,
         rli->sql_thread_caught_up= false;
         DBUG_ASSERT(rli->last_master_timestamp >= 0);
       }
-      if (unlikely(!rli->slave_timestamp))
+
+      if (unlikely(!rli->slave_timestamp) && Log_event::is_group_event(typ))
       {
         /*
           First event for this slave. Assume that all the slave was up to date

sql/sql_repl.cc

@@ -3436,6 +3436,8 @@ int reset_slave(THD *thd, Master_info* mi)
   mi->rli.clear_until_condition();
   mi->rli.clear_sql_delay();
   mi->rli.slave_skip_counter= 0;
+  mi->rli.newest_master_timestamp= 0;
+  mi->rli.slave_timestamp= 0;
 
   // close master_info_file, relay_log_info_file, set mi->inited=rli->inited=0
   end_master_info(mi);