MySQL 5.6 showing wrong "second_behind_master"

Question

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.10.7.98
                  Master_User: replication
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000032
          Read_Master_Log_Pos: 277431436
               Relay_Log_File: mysqld-relay-bin.000039
                Relay_Log_Pos: 143474118
        Relay_Master_Log_File: mysql-bin.000031
             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: 963696099
              Relay_Log_Space: 530952469
              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: 0
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: 98
                  Master_UUID:
             Master_Info_File: /mnt/vol1/mysql/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: updating
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

Here second_behind_master is showing 0 even currently slave is having Relay_Master_Log_File: mysql-bin.000031 and master is having Master_Log_File: mysql-bin.000032.

Answer 1

The seconds_behind_master value simply tells you the difference between the current timestamp on the slave server, and the timestamp on the master at the time the SQL event occurred. Therefore, it shows the difference in time between the slave SQL thread and the slave I/O thread.

From the manual

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

When no event is currently being processed on the slave, this value is 0.

In essence, this field measures the time difference in seconds between the slave SQL thread and the slave I/O thread. If the network connection between master and slave is fast, the slave I/O thread is very close to the master, so this field is a good approximation of how late the slave SQL thread is compared to the master. If the network is slow, this is not a good approximation; the slave SQL thread may quite often be caught up with the slow-reading slave I/O thread, so Seconds_Behind_Master often shows a value of 0, even if the I/O thread is late compared to the master. In other words, this column is useful only for fast networks.

Essentially, you are probably seeing the value of 0 for seconds_behind_master because your network between your slave and master is slow.

Answer 2

The Seconds_Behind_Master may be zero, but you should be looking at other parts of the SHOW SLAVE STATUS\G because it can tell you something about why it's zero. Let's discuss three(3) aspects that will shed some light on Replication's Seconds_Behind_Master.

ASPECT #1

There are occasions when a group of SQL commands are executed individually in the same one-second timeframe. Why does this happen on a Slave?

Keep in mind that the Master may have executed many INSERTs, UPDATEs, and DELETEs, in parallel. However, the binary logs records them as serialized events. An event will include the TIMESTAMP of the SQL command followed by the SQL Command.

If 30 DML commands each took 1 second to complete on a Master at 1399212601 (2014-05-04 10:10:01), they get recorded in the binary logs with the timestamp 1399212601.

On the Slave, when each command is read one-by-one, the timestamp will be 1399212601 for each command. Yet, real-time clock on the server will be steadily increasing. Seconds_Behind_Master is nothing more than UNIX_TIMESTAMP(NOW()) - 1399212601. This is the manifestation of Replication Lag.

ASPECT #2

There are occasions when a group of SQL commands are executed as series of row changes. This could easily happen with row based replication (binlog_format is set to ROW instead of STATEMENT). Individual row changes bloat binary logs and result in same replication lag as stated in ASPECT #1

ASPECT #3

Here are three posts where I discuss how Replication handles LOAD DATA INFILE

• Apr 18, 2013 : Loading data in mysql using LOAD DATA INFILE, replication safe?
• Apr 02, 2013 : MySQL slave stuck in "Reading event from the relay log"?
• Jan 22, 2012 : MySql shell command not replicated to slave

When you execute LOAD DATA INFILE on a Master, the Master will copy the entire CSV file as binlog events into the Binary Logs. The next binlog event recorded is the LOAD DATA INFILE command itself.

The Slave will see a binlog event in its relay logs that will alert the Slave to read the entire CSV file. Then, when it see the LOAD DATA INFILE, it executes it against the temp CSV file in created.

During the manifestation of the temp CSV file, the Seconds_Behind_Master will read 0. Then, when the entire CSV file is made and the LOAD DATA INFILE begins execution, the Seconds_Behind_Master will just increase by 1 or 2. It will do a punctuated jump to hundreds or even thousands of seconds.

SUMMARY

Binary Logs are are to handle group commits for better performance. Notwithstanding, you should looking at the following

• Master_Log_File : Binary Log of the Last Binlog Event recorded on the Master read on the Slave
• Read_Master_Log_Pos : Position of Last Binlog Event that was read from the Master and written to Relay Log on the Slave
• Relay_Master_Log_File : Binary Log of the Last Binlog Event that was read from Master and was executed on Slave
• Exec_Master_Log_Pos : Position of the Last Binlog Event that was read from Master and was executed on Slave
• Relay_Log_Space

If the Relay_Log_Space is changing, then the IO Thread is reading just fine from the network. You can also see that by watching either Master_Log_File or Read_Master_Log_Pos or both changing.

If the Relay_Master_Log_File and/or Exec_Master_Log_Pos is changing, then the command are begin executed on the Slave.

Therefore, once Seconds_Behind_Master is 0 for a long time, look for changes in these five fields in the SHOW SLAVE STATUS\G.