Bug#25407335 SLAVE DON'T REPORT SECONDS_BEHIND_MASTER WHEN RUNNING SLAVE_PARALLEL_WORKERS > 0

Problem:
--------
Slave does not report Seconds_Behind_Master when running
with MTS.

How Seconds_Behind_Master is calculated?
----------------------------------------

When the slave is actively processing updates, Seconds_Behind_Master
shows the difference between the current timestamp on the slave and
the original timestamp logged on the master for the event currently
being processed on the slave.

Seconds_Behind_Master= Current timestamp - mi->rli->last_master_timestamp
                       - mi->clock_diff_with_master

In some cases, slave's clock can be different from master's clock.
In order to support non-identical clocks, 'clock_diff_with_master'
is also taken into consideration so that SBM is correct.

Description:
------------
Coordinator thread, when it finds out that worker queue(GAQ)
is empty, sets rli->last_master_timestamp to zero.  For
any further events, rli->last_master_timestamp is not
updated and thus SBM doesn't show replication lag.

There is also another issue associated with this bug.
When a worker commits a transaction, mts_checkpoint_routine
calls rli->reset_notified_checkpoint function where it sets
the rli->last_master_timestamp.

While doing that, instead of fetching the timestamp from the
first group of the Slave_committed_queue, it fetches the
timestamp from the last checkpoint and assigns it to
rli->last_master_timestamp.

This needs to be fixed as it results in inaccurate SBM.

Fix:
----
rli->last_master_timestamp is assigned from the first
event from the master when all slave workers are
waiting for events from the Coordinator.

When a worker commits a transaction, the coordinator thread
fetches the timestamp from the first group of the
Slave_committed_queue and assigns to rli->last_master_timestamp.

Author: vpvenugo

mysql-test/extra/rpl_tests/rpl_seconds_behind_master_mts_logical_clock.test

@@ -0,0 +1,336 @@
+# ==== Purpose ====
+#
+# Verify that Seconds_Behind_Master is calculated correctly on a
+# Multi-threaded Slave when slave_parallel_type = 'LOGICAL_CLOCK'.
+# The test covers these scenarios:
+#
+# 1) With two workers, check if Seconds_Behind_Master is calculated
+# correctly when two statements are applied in parallel on one database
+# and both the workers are blocked to to lock.
+#
+# 2) With two workers, check if Seconds_Behind_Master is calculated
+# correctly when the first worker is blocked.
+#
+# 3) With three workers, check if Seconds_Behind_Master is calculated
+# correctly when two workers working on table from the same database and
+# 3rd worker working on another database.
+
+--source include/start_slave.inc
+
+###############################################################################
+# Scenario 1: On slave, two statements are applied in parallel on one database.
+# Both workers are blocked.
+###############################################################################
+--echo # Scenario 1: With two workers, check if Seconds_Behind_Master is
+--echo # calculated correctly when two statements are applied in parallel on
+--echo # one database and both the workers are blocked to to lock.
+connect (master2, localhost, root, , );
+
+connection slave;
+
+connection master;
+USE test;
+CREATE TABLE t1 (a int);
+CREATE TABLE t2 (a int);
+
+# We need one statement to be commited so that the parallel
+# statements have a common parent commit
+INSERT INTO t1 SET a=1;
+--source include/sync_slave_sql_with_master.inc
+
+connection slave1;
+LOCK TABLE test.t1 WRITE, test.t2 WRITE;
+
+--connection master1
+let $start= `SELECT UNIX_TIMESTAMP()`;
+BEGIN;
+INSERT INTO t1 SET a=2;
+
+--connection master2
+BEGIN;
+INSERT INTO t2 SET a=4;
+
+--connection master1
+COMMIT;
+--connection master2
+COMMIT;
+
+connection master;
+--source include/sync_slave_io_with_master.inc
+
+# Wait until all workers are blocked by locks. It implies that all
+# transactions are registered into the order commit queue.
+let $wait_condition= SELECT count(*) = 2 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+
+# Sleep on slave so we were at least 3 seconds behind the master
+--real_sleep 3
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $stop= `SELECT UNIX_TIMESTAMP()`;
+let $upper_bound= `SELECT $stop - $start`;
+let $assert_text= Seconds_Behind_Master must be between 3 and upper_bound;
+let $assert_cond= 3 <= $sbm AND $sbm <= $upper_bound;
+--source include/assert.inc
+
+# Unlock tables and allow both workers to complete
+connection slave1;
+UNLOCK TABLES;
+
+connection master;
+--source include/sync_slave_sql_with_master.inc
+
+let $wait_condition= SELECT count(*) = 3 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for an event from Coordinator';
+--source include/wait_condition.inc
+--source include/wait_for_mts_checkpoint.inc
+
+# Now both workers have completed. Thus Seconds_Behind_Master shoud be equal to 0.
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $assert_text= Seconds_Behind_Master must be 0;
+let $assert_cond= $sbm = 0;
+--source include/assert.inc
+
+###############################################################################
+# Scenario 2: Now only the first worker is blocked. Make sure there is a parent
+# commit
+###############################################################################
+--echo # Scenario 2: With two workers, check if Seconds_Behind_Master is
+--echo # calculated correctly when the first worker is blocked.
+
+connection master;
+INSERT INTO t1 SET a=1;
+--source include/sync_slave_sql_with_master.inc
+
+connection slave1;
+LOCK TABLE test.t1 WRITE;
+
+connection slave2;
+LOCK TABLE test.t2 WRITE;
+
+--connection master1
+let $start= `SELECT UNIX_TIMESTAMP()`;
+
+BEGIN;
+INSERT INTO t1 SET a=2;
+
+--connection master2
+BEGIN;
+INSERT INTO t2 SET a=3;
+
+--connection master1
+COMMIT;
+--connection master2
+COMMIT;
+
+connection master;
+--source include/sync_slave_io_with_master.inc
+
+# Wait until both workers are queued and blocked.
+let $wait_condition= SELECT count(*) = 2 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+
+# Now release one worker
+connection slave1;
+UNLOCK TABLES;
+
+# Wait until released worker completes its taks
+let $wait_condition= SELECT count(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+
+# Sleep for 2 seconds so Seconds_Behind_Master was at least 2
+--real_sleep 2
+
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $stop= `SELECT UNIX_TIMESTAMP()`;
+let $upper_bound= `SELECT $stop - $start`;
+let $assert_text= Seconds_Behind_Master must be between 2 and upper_bound;
+let $assert_cond= 2 <= $sbm AND $sbm <= $upper_bound;
+--source include/assert.inc
+
+connection slave2;
+UNLOCK TABLES;
+
+--connection master
+--source include/sync_slave_sql_with_master.inc
+
+# All workers should be done by now.
+let $wait_condition= SELECT count(*) = 3 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for an event from Coordinator';
+--source include/wait_condition.inc
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $assert_text= Seconds_Behind_Master must be 0;
+let $assert_cond= $sbm = 0;
+--source include/assert.inc
+
+###############################################################################
+# Scenario 3: Now there are 3 workers working in pararell. Two workers working
+# on table from the same database and a 3rd worker working on another database
+###############################################################################
+--echo # Scenario 3: With three workers, check if Seconds_Behind_Master is
+--echo # calculated correctly when two workers working on table from the same
+--echo # database and 3rd worker working on another database.
+
+connection master;
+CREATE DATABASE second_test;
+CREATE TABLE second_test.t3 (f1 INT);
+
+# Make sure there is a parent commit
+INSERT INTO test.t1 SET a=1;
+--sync_slave_with_master
+
+# Lock all tables to block all workers.
+connection slave1;
+LOCK TABLE test.t1 WRITE;
+
+connection slave2;
+LOCK TABLE test.t2 WRITE;
+
+connection slave3;
+LOCK TABLE second_test.t3 WRITE;
+
+connect (master_second_test, localhost, root, , );
+
+--connection master_second_test
+BEGIN;
+INSERT INTO second_test.t3 VALUES (1);
+
+--connection master1
+let $start= `SELECT UNIX_TIMESTAMP()`;
+BEGIN;
+INSERT INTO test.t1 SET a=2;
+
+--connection master2
+BEGIN;
+INSERT INTO test.t2 SET a=3;
+
+--connection master_second_test
+COMMIT;
+--connection master1
+COMMIT;
+--connection master2
+COMMIT;
+
+--source include/sync_slave_io_with_master.inc
+
+# Wait for all workers to be queued
+# There should be two workers waiting for locks on test database
+let $wait_condition= SELECT count(*) = 2 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock'
+                                                                             AND Info LIKE 'INSERT INTO test%';
+--source include/wait_condition.inc
+
+# And one worker waiting for the lock on second_database
+let $wait_condition= SELECT count(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock'
+                                                                             AND Info LIKE 'INSERT INTO second_test%';
+--source include/wait_condition.inc
+
+# Make sure that there are 3 overall at the same point in time
+let $wait_condition= SELECT count(*) = 3 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+
+# Wait for 2 seconds so Second_Behind_Master is at least 2
+--real_sleep 2
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $stop= `SELECT UNIX_TIMESTAMP()`;
+let $upper_bound= `SELECT $stop - $start`;
+let $assert_text= Seconds_Behind_Master must be between 2 and upper_bound;
+let $assert_cond= 2 <= $sbm AND $sbm <= $upper_bound;
+--source include/assert.inc
+
+# Lets finish concurrent write on second_test and check if workers on test report
+# correct Seconds_Behind_Master
+connection slave3;
+UNLOCK TABLES;
+
+--real_sleep 1
+
+connection slave;
+# Wait till worker on second_test db finishes
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock'
+                                                                             AND Info LIKE 'INSERT INTO second_test%';
+--source include/wait_condition.inc
+
+# There should be the remaining two workers hanging on test db
+let $wait_condition= SELECT count(*) = 2 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock'
+                                                                             AND Info LIKE 'INSERT INTO test%';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $stop= `SELECT UNIX_TIMESTAMP()`;
+let $upper_bound= `SELECT $stop - $start`;
+let $assert_text= Seconds_Behind_Master must be between 3 and upper_bound;
+let $assert_cond= 3 <= $sbm AND $sbm <= $upper_bound;
+--source include/assert.inc
+
+# Lets finish worker writing to t1
+connection slave1;
+UNLOCK TABLES;
+
+# There should be only one worker left
+let $wait_condition= SELECT count(*) = 1 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for table metadata lock';
+--source include/wait_condition.inc
+let $wait_condition= SELECT count(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Executing event'
+                                                                             OR State = 'update';
+--source include/wait_condition.inc
+
+--real_sleep 1
+
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $stop= `SELECT UNIX_TIMESTAMP()`;
+let $upper_bound= `SELECT $stop - $start`;
+let $assert_text= Seconds_Behind_Master must be between 4 and upper_bound;
+let $assert_cond= 4 <= $sbm AND $sbm <= $upper_bound;
+--source include/assert.inc
+
+# Release last worker
+connection slave2;
+UNLOCK TABLE;
+
+# Wait for all workers to be done
+let $wait_condition= SELECT count(*) = 3 FROM INFORMATION_SCHEMA.PROCESSLIST WHERE State = 'Waiting for an event from Coordinator';
+--source include/wait_condition.inc
+
+# All catched up Seconds_Behind_Master should be 0. Lets wait some more to see if it does not increase
+# Seconds_Behind_Master
+
+--real_sleep 1
+--source include/wait_for_mts_checkpoint.inc
+
+let $sbm= query_get_value("SHOW SLAVE STATUS", Seconds_Behind_Master, 1);
+let $assert_text= Seconds_Behind_Master must be 0;
+let $assert_cond= $sbm = 0;
+--source include/assert.inc
+
+#
+# Cleanup
+#
+connection master;
+DROP TABLE test.t1;
+DROP TABLE test.t2;
+DROP DATABASE second_test;
+
+--source include/sync_slave_sql_with_master.inc
+--source include/stop_slave.inc