MariaDB/MySQL – Seconds Behind Master Deep Dive

seconds_behind_master takes the difference between the timestamp on the Replica minus the timestamp of the event that the SQL_THREAD is processing that (timestamp) that was on the master.

DEMO

Execute the script below in Master Server.

create database if not exists sbm_db;

USE `sbm_db`;
DROP procedure IF EXISTS `gendata`;

DELIMITER $$
CREATE PROCEDURE gendata (in loopLimit int)
BEGIN
	declare c int;
    set c = 0;
    
    label: LOOP
		insert into tbl (fld)
        values (FLOOR(1 + (RAND() * 60000)));
        set c = c + 1;
        if c > loopLimit then
			leave label;
        end if;
    end LOOP label;
END$$

DELIMITER ;


drop table if exists tbl;
create table tbl (
tblId int not null primary key auto_increment,
fld varchar(255),
updatedAt timestamp not null default current_timestamp
);

Execute in Replica

STOP SLAVE SQL_THREAD;

Execute in Master

call `gendata`(3000);

mysql> SELECT COUNT(*) FROM tbl;
+----------+
| COUNT(*) |
+----------+
|     3000 |
+----------+

In the Replica, since the SQL_THREAD is not running, these records don’t exists.

mysql> SELECT COUNT(*) FROM tbl;
+----------+
| COUNT(*) |
+----------+
|        0 |
+----------+

Now, run these commands in one shot in the Replica to start the SQL_THREAD, get the unix_timestamp(), then stop the SQL_THREAD again.

START SLAVE SQL_THREAD;

SHOW SLAVE STATUS \G

SELECT unix_timestamp();

STOP SLAVE SQL_THREAD;

SELECT COUNT(*) FROM tbl;

Below are my output.

mysql> START SLAVE SQL_THREAD;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> SHOW SLAVE STATUS \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.33.17
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: db1-bin.000018
          Read_Master_Log_Pos: 3349116
               Relay_Log_File: mysqldb2-relay-bin.000006
                Relay_Log_Pos: 2512613
        Relay_Master_Log_File: db1-bin.000018
             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: 2512410
              Relay_Log_Space: 3349604
              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: 93
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:


mysql> SELECT unix_timestamp();
+------------------+
| unix_timestamp() |
+------------------+
|       1621660163 |
+------------------+
1 row in set (0.00 sec)


mysql> STOP SLAVE SQL_THREAD;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> SELECT COUNT(*) FROM tbl;
+----------+
| COUNT(*) |
+----------+
|      552 |
+----------+
1 row in set (0.00 sec)

You might be wondering, why seconds behind master is 93 when there were only 5 seconds of worth of data?

How seconds master works is it takes the difference between the timestamp on the replica minus the timestamp of the event that the sql thread is processing (The timestamp that is on the master).

mysqlbinlog --base64-output="decode-rows" --verbose mysqldb2-relay-bin.000006 | less

# at 2512613
#210522  1:07:50 server id 1  end_log_pos 2512485       GTID    last_committed=9012     sequence_number=9013    rbr_only=yes    original_committed_timestamp=1621660070   immediate_commit_timestamp=1621660070915181     transaction_length=279

mysql> select 1621660163 - 1621660070;
+-------------------------+
| 1621660163 - 1621660070 |
+-------------------------+
|                      93 |
+-------------------------+

Cheers!