Bug #56363 Wrong value for Seconds_Behind_Master at moment of rotation of the relay log

Submitted: 30 Aug 2010 11:51 Modified: 3 Sep 2010 9:42
Reporter: Serge Kozlov Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:5.6.99-m5 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: nuts, replication, Seconds_Behind_Master

[30 Aug 2010 11:51] Serge Kozlov 
Description:
At moment of rotation of the relay log file the value of Seconds_Behind_Master  is wrong. Test with with max-binlog-size=100M shows the following results:

15:29:59. Before rotation: Seconds_Behind_Master  = 1
15:30:00. At moment of rotation: Seconds_Behind_Master  = 149
15:30:00. After rotation: Seconds_Behind_Master  = 2

The dumps below contain the current time and SHOW SLAVE STATUS at three moments in details:

mysql> select now(); show slave status\G
+---------------------+
| now()               |
+---------------------+
| 2010-08-30 15:29:59 |
+---------------------+
1 row in set (0.00 sec)

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: root
                  Master_Port: 10000
                Connect_Retry: 60
              Master_Log_File: 1.000002
          Read_Master_Log_Pos: 2170
               Relay_Log_File: vtop-relay-bin.000002
                Relay_Log_Pos: 99195148
        Relay_Master_Log_File: 1.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: 99195010
              Relay_Log_Space: 101786354
              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: 1
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 91ca26be-b429-11df-8456-0800272f46ab
             Master_Info_File: /home/ksm/oracle/nuts/var/data/rep::general::general_basic-row/2/5.6.99-m5/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Reading event from the relay log
1 row in set (0.00 sec)

mysql> select now(); show slave status\G
+---------------------+
| now()               |
+---------------------+
| 2010-08-30 15:30:00 |
+---------------------+
1 row in set (0.00 sec)

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: root
                  Master_Port: 10000
                Connect_Retry: 60
              Master_Log_File: 1.000002
          Read_Master_Log_Pos: 2170
               Relay_Log_File: vtop-relay-bin.000002
                Relay_Log_Pos: 99195148
        Relay_Master_Log_File: 1.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: 99195010
              Relay_Log_Space: 101786199
              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: 149
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 91ca26be-b429-11df-8456-0800272f46ab
             Master_Info_File: /home/ksm/oracle/nuts/var/data/rep::general::general_basic-row/2/5.6.99-m5/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Reading event from the relay log
1 row in set (0.03 sec)

mysql> select now(); show slave status\G
+---------------------+
| now()               |
+---------------------+
| 2010-08-30 15:30:00 |
+---------------------+
1 row in set (0.00 sec)

*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 127.0.0.1
                  Master_User: root
                  Master_Port: 10000
                Connect_Retry: 60
              Master_Log_File: 1.000002
          Read_Master_Log_Pos: 2170
               Relay_Log_File: vtop-relay-bin.000003
                Relay_Log_Pos: 210
        Relay_Master_Log_File: 1.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: 99195010
              Relay_Log_Space: 101786199
              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: 2
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1
                  Master_UUID: 91ca26be-b429-11df-8456-0800272f46ab
             Master_Info_File: /home/ksm/oracle/nuts/var/data/rep::general::general_basic-row/2/5.6.99-m5/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Reading event from the relay log
1 row in set (0.01 sec)

How to repeat:
1. Run master->slave replication
2. Generate statements on master
3. Run (and store results) on slave several times per second:
 select now(); show slave status\G
4. Check results on slave at moment of relay log rotation.
[2 Sep 2010 11:27] Luis Soares 
See also: BUG#53167.
[2 Sep 2010 11:35] Luis Soares 
See also: BUG#52166.
[3 Sep 2010 9:42] Daogang Qu 
The displayed value for Seconds_Behind_Master is calculated based on
the timestamp of the Format_Description_Log_Event, which is reinserted
into stream of events in relay log when relay log rotates. This can
be a wrong big number due to the old timestamp from the FD.

Duplicate with BUG#53167
[6 Jan 2014 18:00] MySQL Verification Team 
This problem can be triggered when the slave and master have the same server-id, causing events that will rotate the relay log at a very high rate.  When the log rotates a spike in SBM is seen.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.043 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.