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 Manuel Oliveira Soares
See also: BUG#53167.
[2 Sep 2010 11:35] Luis Manuel Oliveira 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.