MySQL replication lagging behind with log_slave_updates

Question

I'm in the process of setting up replication in this topology:

   /--B
A-
   \--C--D

In order to achieve this I need log_slave_updates to be enabled on C, so D will also get the changes from A.

C is a pretty beefy server. Amazon EC2-based. 32 cores, 250GB memory and 20000 IOPS data volume. It's more powerful than A, which has less CPU power, memory and 3200 IOPS on its main disk.

As soon as I turn on log_slave_updates on C, it almost immediately falls behind A. This is odd to me because I would expect it to easily outperform, and in my mind log_slave_updates is just writing its log to disk.

I don't know where to start debugging this.

Edit Thanks for your follow-up questions, I added a bit more information here:

I did indeed create the EBS volume from a snapshot, but I warmed it up by reading every byte using dd this took a few days.

Output of SELECT @@INNODB_FLUSH_LOG_AT_TRX_COMMIT, @@SYNC_BINLOG\G is:

@@INNODB_FLUSH_LOG_AT_TRX_COMMIT: 2
@@SYNC_BINLOG: 1

This is the output of SHOW SLAVE STATUS a few minutes after turning log_slave_updates on again:

               Slave_IO_State: Waiting for master to send event
                  Master_Host: anonimized
                  Master_User: repl
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.001253
          Read_Master_Log_Pos: 969363410
               Relay_Log_File: mysql-relay-bin.002984
                Relay_Log_Pos: 44865262
        Relay_Master_Log_File: mysql-bin.001253
             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: 910276312
              Relay_Log_Space: 103952567
              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: 259
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: 8c7641ba-a380-11e5-a8ee-0e920570e8cb
             Master_Info_File: /mnt/mysql-data/database/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: 
            Executed_Gtid_Set: 
                Auto_Position: 0
         Replicate_Rewrite_DB: 
                 Channel_Name: 
           Master_TLS_Version: 

iostat -x when log_slave_updates is on:

Linux 4.4.0-53-generic (hostname)   01/07/2017      _x86_64_        (32 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.91    0.00    0.24    1.78    0.00   97.06

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.00    23.56    0.32   50.91    23.53   467.96    19.19     0.29    5.65    9.03    5.63   5.26  26.93
xvdf              0.00    61.33   93.76  163.17  9468.94  8128.52   136.98     1.14    4.44    8.68    2.00   1.89  48.48

iostat -x when log_slave_updates is off:

Linux 4.4.0-53-generic (hostname)   01/07/2017      _x86_64_        (32 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.91    0.00    0.24    1.78    0.00   97.07

Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda              0.00    23.55    0.32   50.89    23.52   467.82    19.19     0.29    5.65    9.03    5.63   5.26  26.92
xvdf              0.00    61.60   93.71  163.54  9463.81  8131.70   136.79     1.14    4.43    8.68    2.00   1.88  48.48

Answer 1

First of all, you need to rely on SHOW SLAVE STATUS\G

Let's take a sample display from an old answer of mine : MySQL Replication Lag Behaving Erraticly. In the display, please note the items that can help you sense measure replication

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.17.20.102
                  Master_User: replicant
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.002814
          Read_Master_Log_Pos: 823078734
               Relay_Log_File: relay-bin.007364
                Relay_Log_Pos: 823078879
       Relay_Master_Log_File: mysql-bin.002814
             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: 823078734
              Relay_Log_Space: 823079071
              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:
1 row in set (0.00 sec)

Here are the items

• Seconds_Behind_Master : The number of seconds behind the slave is from the master based on the time in the Slave's OS minus the TIMESTAMP of the latest query processed on the Slave.
• Relay_Log_Space : Total number of bytes collected on the Slave from the Master yet to be processed
• (Master_Log_File,Read_Master_Log_Pos) : The latest binlog entry from the Master to be recorded in the Slave's Relay Logs.
• (Relay_Master_Log_File,Exec_Master_Log_Pos) : The latest binlog entry from the Master to be executed in the Slave.

Lag can only be measured, or at least noticed, by observing one or more of the following:

• Seconds_Behind_Master keeps increasing
• Master_Log_File and Relay_Master_Log_File are not the same (binlog events are being collected faster that the SQL thread can process them)
• Exec_Master_Log_Pos is not moving even if Slave_SQL_Running: Yes (This could be a long running query or possibly a very large transaction commit)
• Relay_Log_Space is increasing steadily
  • Indicates amount of binlog events collected
  • This could mean slow collection of binlog events over the network

I sometimes see lag increasing because of taking a large mysqldump and loading it hours later (even a day later). When starting up replication for the first time, the apparent numerical lag in Seconds would disappear after several hours (or even a day) out of nowhere.

Please note that there is only one SQL thread for replication. All queries are processed sequentially. How does this affect replication lag ???

Suppose the Master executed 300 inserts, updates, and deletes in the same second and each query took 1 second to run. Here is what is actually happening:

• All queries are serialized when written into the Master's binary logs
• The Slave reads the binlog events from the Master ONE AT A TIME !!!
• The Slave executes the binlog events it recorded ONE AT A TIME !!!
• Seconds_Behind_Master would actually increase by 300 seconds (5 minutes)
• Keep in mind that the result of transaction could be huge and cannot be applied until all the binlog events making up the one transaction is completely written into the relay logs on the Master (This can usually occur with ROW based replication). This also contributes to increased lag.

I have discussed MySQL Replication Lag many times over the years.

Even with the beefiest scaled-up Slave, it will only process one SQL transaction at a time. A beefy Master would make sense if you eventually failover to such server and promote it to a Master.

In conclusion, please keep your eye on these things as the Slave eventually catches up.

UPDATE 2017-01-07 17:21 EST

Here is what I find disturbing about turning on log_slave_updates

Relay Logs and Binary Logs are sequentially written. The tablespace files for InnoDB tables (.ibd) experience random writes. If sequential and random writes occur on the same disk, you can very sure the random writes will become the bottleneck of sequential writes.

Perhaps if you store your Relay Logs and Binary Logs on a volume separate from the data, then the sequential writes on those logs will increase in speed.

In the DBA StackExchange, I referred to a FaceBook Engineer eight(8) times who splits up data from logs for MySQL setups. Please see my posts on them.. This is a must since writes to relay logs are a must and log_slave_updates tends to suffer.

In those posts, I also suggest tuning InnoDB. In your case, I would tune the following:

• innodb_read_io_threads : set to 8 (or 16 if you need faster reads)
• innodb_writes_io_threads : set to 8 (or 16 if you need faster writes)
• innodb_buffer_pool_instances : set it to 32 (number of cores)

If your MySQL instances has multiple databases in it, then set

• slave_parallel_workers to the number of tenant databases
• slave_preserve_commit_order to 1

Answer 2

Ultimately I found that adding extra disks (even raiding it), and changing all the suggested settings from Rolando did not help me.

The one thing that did was:

sync_binlog=0

This setting will cause mysql to not flush binlogs to disk, but instead let the operating system make this decision. This might not be as safe as letting mysql do it, so use at your own risk.

For me it's a great solution because I'm only setting up chained replication to migrate, so it's a temporary measure.