[MDEV-25999] Unrealistic "Seconds behind master" value Created: 2021-06-23  Updated: 2022-09-30  Resolved: 2022-09-30

Status: Closed
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.2
Fix Version/s: 10.2.42

Type: Bug Priority: Major
Reporter: Niranjan Assignee: Angelique Sklavounos (Inactive)
Resolution: Fixed Votes: 0
Labels: None


 Description   

== Unrealistic "Seconds behind master" value reported in "Show slave status"
== It shows a very huge value.
== This happens when we check seconds behind master exactly at the time after Binary log rotation on the master.

Able to reproduce the issue on 10.2.38.
Based on the release notes, 10.2.39 was released yesterday. But the binaries are not yet available for download. So, couldn't check it on 10.2.39
[+] https://mariadb.com/kb/en/release-notes-mariadb-102-series/

 Comments   
Comment by Niranjan [ 2021-06-23 ]

STEPS TO REPRODUCE THE ISSUE:

== Set up replication between two MariaDB servers (running on 10.2.38)
== I do not have any other query running on the DB.
== On the "Primary" server, repeatedly flush the binary logs:
I did something like this:
flush binary logs;show binary logs;select now(),sleep(0.25);flush binary logs;show binary logs;select now(),sleep(0.25)... .... .... .... ... ...

== On the "replica" server, repeatedly monitor the seconds behind master by running "show slave status\G"

== I have grepped the output to show only the required details. Pasting a part of it below:

Replica_Output

–
Relay_Master_Log_File: mysql-bin-changelog.000455
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 307
1 row in set (0.01 sec)

–
Relay_Master_Log_File: mysql-bin-changelog.000470
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1650
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000472
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1650
1 row in set (0.01 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000474
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1651
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000476
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1651
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000482
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1653
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000496
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1659
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000498
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1660
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000500
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1660
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000510
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1663
1 row in set (0.01 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000512
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1663
1 row in set (0.00 sec)

–
--
Relay_Master_Log_File: mysql-bin-changelog.000514
Exec_Master_Log_Pos: 4
Seconds_Behind_Master: 1664
1 row in set (0.02 sec)

Looking at the binary logs of the "Primary" instance corresponding to "Relay_Master_Log_File" and "Exec_Master_Log_Pos", I can just see that its the starting of the file (immediately after rotation of older file).

MASTER> show binlog events in 'mysql-bin-changelog.000455';
 
+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+
 
| Log_name                   | Pos | Event_type        | Server_id | End_log_pos | Info                                           |
 
+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+
 
| mysql-bin-changelog.000455 |   4 | Format_desc       |       123 |         256 | Server ver: 10.2.38-MariaDB-log, Binlog ver: 4 |
 
| mysql-bin-changelog.000455 | 256 | Gtid_list         |       123 |         299 | [0-123-1]                                      |
 
| mysql-bin-changelog.000455 | 299 | Binlog_checkpoint |       123 |         352 | mysql-bin-changelog.000454                     |
 
| mysql-bin-changelog.000455 | 352 | Binlog_checkpoint |       123 |         405 | mysql-bin-changelog.000455                     |
 
| mysql-bin-changelog.000455 | 405 | Rotate            |       123 |         462 | mysql-bin-changelog.000456;pos=4               |
 
+----------------------------+-----+-------------------+-----------+-------------+------------------------------------------------+
 
5 rows in set (0.00 sec)

—
Another important observation is that the "seconds behind master" value keeps increasing.
You can refer the above output itself. Each time wrong value is returned, it is greater than the previous value.

Comment by Andrei Elkin [ 2022-05-30 ]

bnestere, could you please verify whether the description fits to the fixed MDEV-16091?

Comment by Angelique Sklavounos (Inactive) [ 2022-09-30 ]

It was possible to reproduce this with 10.2.38 by following the steps in the first comment and using a script to output SHOW SLAVE STATUS\G to a file in an infinite loop until manually killed. Grepping for "Slave_SQL_Running_State: Reading event from the relay log" would sometimes show Seconds_Behind_Master as a value on the order of hundreds or thousands of seconds, and always increasing, as described.

The issue no longer appears in 10.2.42, and testing showed that commit 96de6bf did not have the behavior, while the parent commit 452c9a4 still had the issue.

Generated at Thu Feb 08 09:41:59 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.