MySQL replication - slave is continuously lagging behind master

Question

I am using MySQL-5.1.50 with a Master-slave replication setup.

Most of the time the slave is lagging behind the master.

When I run show processlist;, there is no query that's taking a long time. I enabled slow_log as well. However, it does not find any slow running query.

The slave is continuously giving alerts that replication is seconds behind the master. Sometimes, the lag time increases.

How do I diagnose the cause of the problem?

I need urgent help, since this problem has persisted for the last 20 days.

Answer 1

The Seconds_Behind_Master is really like viewing the past via time travel.

Think of it this way:

• The Sun is 93,000,000 miles away from the Earth
• The speed of light is 186,000 miles/sec
• Simple division shows that it takes roughly 500 sec (8 min 20 sec) for the Sun's light to reach Earth
• When you look at the Sun, you actually don't see the Sun. You see where it was 8 min 20 sec ago.

In like manner, it seems that the Master is processing a lot of queries at the same time.

You look back at the Slave, run SHOW SLAVE STATUS\G and it says 200 for Seconds_Behind_Master. How is that number calculated? Slave's Clock Time (UNIX_TIMESTAMP(NOW()) - TIMESTAMP of the Query when it was completed and recorded in the Master's Binary Log.

There is another metric to look at besides Seconds_Behind_Master. That metric is called Relay_Log_Space. That represents the sum of all bytes for all relay files on the Slave. By default, the largest single relay log is limited to 1GB. If Relay_Log_Space is less than 1GB, this indicates that many long running queries executed on the Master in parallel. Unfortunately, due to the single-threaded nature Replication's SQL thread, queries are executed one behind the other.

For example, suppose you have the following scenario on the Master:

• Slow Query log is enabled
• 20 queries executed in parallel on the Master
• Each query took 3 seconds
• Each query get recorded in the Master Binary Log with the same timestamp

When the Slave reads those queries from its relay log and processes them one by one

• the Slave's Clock will be moving
• the TIMESTAMP for each of the 20 queries will be identical
• the difference will increasing 3 seconds be completed query
• this results in 60 seconds for Seconds_Behind_Master

Concerning the Slow Log, the default for long_query_time is 10 seconds. If all your queries in the relay logs are less than 10 seconds, you will never catch anything in the Slow Query Log.

I have the following recommendations for both Master and Slave servers

• RECOMMENDATION #1 : Upgrade to MySQL 5.5. Under MySQL 5.5 and Percona Server 5.1.38+, you can tune InnoDB to access multiple CPUs. I have written past posts about this
  • Apr 26, 2012 : Is the CPU performance relevant for a database server?
  • Sep 20, 2011 : Multi cores and MySQL Performance
  • Sep 12, 2011 : Possible to make MySQL use more than one core?
  • May 26, 2011 : About single threaded versus multithreaded databases performance
• RECOMMENDATION #2 : Use InnoDB for all tables. InnoDB caches data and indexes in RAM, MyISAM only caches indexes.
• RECOMMENDATION #3 : Increase RAM. You must cache more data and indexes on the Slave and Master alike
• RECOMMENDATION #4 : Tune all queries. Reducing milliseconds from queries that run hundreds of times goes a long way to reduce Seconds_Behind_Master.

FURTHER TROUBLESHOOTING

If you want to see the queries causing the replciation lag, do the following:

• SHOW SLAVE STATUS\G
• Get name of relay log from Relay_Log_File
• STOP SLAVE;
• START SLAVE;
• In the OS, cd /var/lib/mysql or wherever the relay logs are written
• Dump the relay log to a text file

For example, Let's do SHOW SLAVE STATUS\G

               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.64.51.149
                  Master_User: replicant
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000009
          Read_Master_Log_Pos: 1024035856
               Relay_Log_File: relay-bin.000030
                Relay_Log_Pos: 794732078
        Relay_Master_Log_File: mysql-bin.000009
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB: search_cache
           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: 1024035856
              Relay_Log_Space: 794732271
              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: 106451149

If I run STOP SLAVE; START SLAVE;, the relay log closes and a new one is open. Yet, you want relay-bin.000030.

Dump the contents as follows:

cd /var/lib/mysql
mysqlbinlog relay-bin.000030 > /root/RelayLogQueries.txt
less /root/RelayLogQueries.txt

You can now see the queries the Slave is currently trying to process. You can use those queries as the starting point for tuning.

Answer 2

What binary log format are you using ? Are you using ROW or STATEMENT ?
"SHOW GLOBAL VARIABLES LIKE 'binlog_format';"

If you are using ROW as a binlog format make sure that all your tables has Primary or Unique Key:
SELECT t.table_schema,t.table_name,engine FROM information_schema.tables t INNER JOIN information_schema .columns c on t.table_schema=c.table_schema and t.table_name=c.table_name and t.table_schema not in ('performance_schema','information_schema','mysql') GROUP BY t.table_schema,t.table_name HAVING sum(if(column_key in ('PRI','UNI'), 1,0)) =0;

If you execute e.g. one delete statement on the master to delete 1 million records on a table without a PK or unique key then only one full table scan will take place on the master's side, which is not the case on the slave.
When ROW binlog_format is being used, MySQL writes the rows changes to the binary logs (not as a statement like STATEMENT binlog_format) and that change will be applied on the slave's side row by row, which means a 1 million full table scan will take place on the slave's to reflect only one delete statement on the master and that is causing slave lagging problem.

Answer 3

The seconds_behind_master value in SHOW SLAVE STATUS is the difference between the system time on the master, which got stored when the event was originally executed and recorded in the binary log... and the system time on the slave when the event gets executed there.

Seconds behind master will give incorrect values if the two systems' clocks aren't in sync.