How to Identify and Cure MySQL Replication Slave Lag

this post was originally written by muhammad irfan

here on the percona mysql support team, we often see issues where a customer is complaining about replication delays – and many times the problem ends up being tied to mysql replication slave lag. this of course is nothing new for mysql users and we’ve had a few posts here on the mysql performance blog on this topic over the years (two particularly popular post in the past were: “ reasons for mysql replication lag ” and “ managing slave lag with mysql replication ,” both by percona ceo peter zaitsev) .

in today’s post, however, i will share some new ways of identifying delays in replication – including possible causes of lagging slaves – and how to cure this problem.

how to identify replication delay

mysql replication works with two threads, io_thread & sql_thread. io_thread connects to a master, reads binary log events from the master as they come in and just copies them over to a local log file called relaylog . on the other hand, sql_thread reads events from a relay log stored locally on the replication slave (the file that was written by io thread) and then applies them as fast as possible. whenever replication delays, it’s important to discover first whether it’s delaying on slave io_thread or slave sql_thread.

normally, i/o thread would not cause a huge replication delay as it is just reading the binary logs from the master. however, it depends on the network connectivity, network latency… how fast is that between the servers. the slave i/o thread could be slow because of high bandwidth usage. usually, when the slave io_thread is able to read binary logs quickly enough it copies and piles up the relay logs on the slave – which is one indication that the slave io_thread is not the culprit of slave lag.

on the other hand, when the slave sql_thread is the source of replication delays it is probably because of queries coming from the replication stream are taking too long to execute on the slave. this is sometimes because of different hardware between master/slave, different schema indexes, workload. moreover, the slave oltp workload sometimes causes replication delays because of locking. for instance, if a long-running read against a myisam table blocks the sql thread, or any transaction against an innodb table creates an ix lock and blocks ddl in the sql thread. also, take into account that slave is single threaded prior to mysql 5.6, which would be another reason for delays on the slave sql_thread.

let me show you via master status/slave status example to identify either slave is lagging on slave io_thread or slave sql_thread.

mysql-master> show master status;
+------------------+--------------+------------------+------------------------------------------------------------------+
| file | position  | binlog_do_db | binlog_ignore_db | executed_gtid_set                                                |
+------------------+--------------+------------------+------------------------------------------------------------------+
| mysql-bin.018196 | 15818564     |                  | bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:1-2331947                   |
+------------------+--------------+------------------+------------------------------------------------------------------+
mysql-slave> show slave status\g
*************************** 1. row ***************************
slave_io_state: queueing master event to the relay log
master_host: master.example.com
master_user: repl
master_port: 3306
connect_retry: 60
master_log_file: mysql-bin.018192
read_master_log_pos: 10050480
relay_log_file: mysql-relay-bin.001796
relay_log_pos: 157090
relay_master_log_file: mysql-bin.018192
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: 5395871
relay_log_space: 10056139
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: 230775
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: 2
master_uuid: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166
master_info_file: /var/lib/mysql/i1/data/master.info
sql_delay: 0
sql_remaining_delay: null
slave_sql_running_state: reading event from the relay log
master_retry_count: 86400
master_bind:
last_io_error_timestamp:
last_sql_error_timestamp:
master_ssl_crl:
master_ssl_crlpath:
retrieved_gtid_set: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166
executed_gtid_set: bb11b389-d2a7-11e3-b82b-5cf3fcfc8f58:2-973166,
ea75c885-c2c5-11e3-b8ee-5cf3fcfc9640:1-1370
auto_position: 1

this clearly suggests that the slave io_thread is lagging and obviously because of that the slave sql_thread is lagging, too, and it yields replication delays. as you can see the master log file is mysql-bin.018196 (file parameter from master status) and slave io_thread is on mysql-bin.018192 ( master_log_file from slave status ) which indicates slave io_thread is reading from that file, while on master it’s writing on mysql-bin.018196 , so the slave io_thread is behind by 4 binlogs. meanwhile, the slave sql_thread is reading from same file i.e. mysql-bin.01819 2 (relay_master_log_file from slave status) this indicates that the slave sql_thread is applying events fast enough, but it’s lagging too, which can be observed from the difference between read_master_log_pos & exec_master_log_pos from show slave status output.

you can calculate slave sql_thread lag from read_master_log_pos – exec_master_log_pos in general as long as master_log_file parameter output from show slave status and relay_master_log_file parameter from show slave status output are the same. this will give you rough idea how fast slave sql_thread is applying events. as i mentioned above, the slave io_thread is lagging as in this example then off course slave sql_thread is behind too. you can read detailed description of show slave status output fields here.

also, the seconds_behind_master parameter shows a huge delay in seconds. however, this can be misleading, because it only measures the difference between the timestamps of the relay log most recently executed, versus the relay log entry most recently downloaded by the io_thread. if there are more binlogs on the master, the slave doesn’t figure them into the calculation of seconds_behind_master.  you can get a more accurate measure of slave lag using pt-heartbeat from percona toolkit. so, we learned how to check replication delays – either it’s slave io_thread or slave sql_thread. now, let me provide some tips and suggestions for what exactly causing this delay.

tips and suggestions what causing replication delay & possible fixes

usually, the slave io_thread is behind because of slow network between master/slave. most of the time, enabling slave_compressed_protocol helps to mitigate slave io_thread lag. one other suggestion is to disable binary logging on slave as it’s io intensive too unless you required it for point in time recovery.

to minimize slave sql_thread lag, focus on query optimization. my recommendation is to enable the configuration option log_slow_slave_statements so that the queries executed by slave that take more than long_query_time will be logged to the slow log. to gather more information about query performance, i would also recommend setting the configuration option log_slow_verbosity to “full”.

this way we can see if there are queries executed by slave sql_thread that are taking long time to complete. you can follow my previous post about how to enable slow query log for specific time period with mentioned options here .  and as a reminder,  log_slow_slave_statements as variable were first introduced in percona server 5.1 which is now part of vanilla mysql from version 5.6.11 in upstream version of mysql server log_slow_slave_statements were introduced as command line option. details can be found here while log_slow_verbosity is percona server specific feature.

one another reason for delay on slave sql_thread if you use row based binlog format is that if your any database table missing primary key or unique key then it will scan all rows of the table for dml on slave and causes replication delays so make sure all your tables should have primary key or unique key. check this bug report for details http://bugs.mysql.com/bug.php?id=53375 you can use below query on slave to identify which of database tables missing primary or unique key.

mysql> 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
group by t.table_schema,t.table_name
having sum(if(column_key in ('pri','uni'), 1,0)) =0;

one improvement is made for this case in mysql 5.6, where in memory hash is used slave_rows_search_algorithms comes to the rescue.

note that seconds_behind_master is not updated while we read huge rbr event, so, “lagging” may be related to just that – we had not completed reading of the event. for example, in row based replication huge transactions may cause delay on slave side e.g. if you have 10 million rows table and you do “delete from table where id < 5000000″ 5m rows will be sent to slave, each row separately which will be painfully slow. so, if you have to delete oldest rows time to time from huge table using partitioning might be good alternative for this for some kind of workloads where instead using delete use drop old partition may be good and only statement is replicated because it will be ddl operation.

to explain it better, let suppose you have partition1 holding rows of id’s from 1 to 1000000 , partition2 – id’s from 1000001 to 2000000 and so on so instead of deleting via statement “delete from table where id<=1000000;” you can do “alter table drop partition1;” instead. for alter partitioning operations check manual – check this wonderful post too from my colleague roman explaining possible grounds for replication delays here

pt-stalk is one of finest tool from percona toolkit which collects diagnostics data when problems occur. you can setup pt-stalk as follows so whenever there is a slave lag it can log diagnostic information which we can be later analyze to check to see what exactly causing the lag.

here is how you can setup pt-stalk so that it captures diagnostic data when there is slave lag:

------- pt-plug.sh contents
#!/bin/bash
trg_plugin() {
mysqladmin $ext_argv ping &> /dev/null
mysqld_alive=$?
if [[ $mysqld_alive == 0 ]]
then
seconds_behind_master=$(mysql $ext_argv -e "show slave status" --vertical | grep seconds_behind_master | awk '{print $2}')
echo $seconds_behind_master
else
echo 1
fi
}
# uncomment below to test that trg_plugin function works as expected
#trg_plugin
-------
-- that's the pt-plug.sh file you would need to create and then use it as below with pt-stalk:
$ /usr/bin/pt-stalk --function=/root/pt-plug.sh --variable=seconds_behind_master --threshold=300 --cycles=60 --notify-by-email=muhammad@example.com --log=/root/pt-stalk.log --pid=/root/pt-stalk.pid --daemonize

you can adjust the threshold, currently its 300 seconds, combining that with –cycles, it means that if seconds_behind_master value is >= 300 for 60 seconds or more then pt-stalk will start capturing data. adding –notify-by-email option will notify via email when pt-stalk captures data. you can adjust the pt-stalk thresholds accordingly so that’s how it triggers to collect diagnostic data during problem.

conclusion

a lagging slave is a tricky problem but a common issue in mysql replication. i’ve tried to cover most aspects of replication delays in this post. please share in the comments section if you know of any other reasons for replication delay.