3

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
  • SELECT @@INNODB_FLUSH_LOG_AT_TRX_COMMIT, @@SYNC_BINLOG; What values do you have? – Michael - sqlbot Jan 6 '17 at 22:36
  • Also, how did you create the volume on C? Was it a new, blank volume, or did you create it from an EBS snapshot? – Michael - sqlbot Jan 6 '17 at 22:38
  • If A is doing a lot of things in parallel, and C is not set up with any parallelism, then C can get behind. – Rick James Jan 7 '17 at 0:00
  • Thanks @Michael-sqlbot, I added the information you asked for. I did indeed restore from a snapshot but warmed this disk first. – Evert Jan 7 '17 at 19:29
  • Capture a few sequential lines of the relevant disk's behavior using iostat -x 1. Also, what is the instance type? – Michael - sqlbot Jan 7 '17 at 19:42
2

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:

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

  • Hi! Thanks for your super detailed answer. I added output of SHOW SLAVE STATUS. We are indeed seeing an increasing Seconds_Behind_Master, Relay_Log_Space. Master_Log_File and Relay_Master_Log_File are still the same, but not for long. The odd thing is that this really only happens with log_slave_updates on. As soon as I flip that switch, Second_Behind_Master really quickly drops to 0. – Evert Jan 7 '17 at 19:32
  • That's some really extensive advice. I'm going to give this a shot on monday. Thanks for all your effort so far, hugely appreciated – Evert Jan 8 '17 at 21:39
  • I followed all your suggestions, including adding a disk specifically for logs. No luck for all of them. Ultimately I found that setting sync_binlog=0 fixed my problem. I don't see this as a permanent solution, but it will help me make the migration. Thanks for your awesome answers. – Evert Jan 11 '17 at 16:39
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.

  • 1
    While there is tiny, tiny risk of missing transactions making it to the binlog, at least the data is written. So, congrats on solving this one yourself !!! – RolandoMySQLDBA Jan 11 '17 at 17:26
  • Hey, I have another suggestion you might find interesting. You could set sync_binlog=100 so that every 100 writes to the binlog, there is a flush to disk. That way, so can control how often to throttle binlog writes. You could set it to 1000 or 10000 if your database has high write volume. See the sync_binlog docs (dev.mysql.com/doc/refman/5.6/en/…) – RolandoMySQLDBA Jan 11 '17 at 22:04

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.