MySQL slave taking too long on "Queueing master event to the relay log"

Question

I have two mysql mysql slave servers. The DB version is:

mysql> show variables like '%version%';
+-------------------------+-----------------------------------------------------+
| Variable_name           | Value                                               |
+-------------------------+-----------------------------------------------------+
| innodb_version          | 1.1.8-rel29.4                                       |
| protocol_version        | 10                                                  |
| slave_type_conversions  |                                                     |
| version                 | 5.5.29-29.4-log                                     |
| version_comment         | Percona Server (GPL), Release rel29.4, Revision 401 |
| version_compile_machine | x86_64                                              |
| version_compile_os      | Linux                                               |
+-------------------------+-----------------------------------------------------+
7 rows in set (0.00 sec)

A developer had to rebuild a big table on master, after which the slave's status is shown as:

show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Queueing master event to the relay log
                  Master_Host: 10.140.10.31
                  Master_User: replicator
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000100
          Read_Master_Log_Pos: 246814935
               Relay_Log_File: relay-bin.000002
                Relay_Log_Pos: 163153081
        Relay_Master_Log_File: mysql-bin.000100
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: temp
           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: 244925740
              Relay_Log_Space: 165042426
              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: 10
1 row in set (0.01 sec)

The Seconds_Behind_Master: 0 value changes from 0 a large number for a short period and then comes back to 0 again. I have seen that the changes on the master DB has not been written to slaves yet.

I have checked the DISK activity on slaves and DISK utilization is still very high, which indicates that it is writing to the relay logs:

# iostat -dx 1
Linux 2.6.32-279.19.1.el6.centos.plus.x86_64 (hmg-slave-hoteldata2)     09/04/2014      _x86_64_        (4 CPU)

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.01     8.99    0.49    9.65    23.04   213.78    23.34     0.05    4.45   2.28   2.31
dm-0              0.00     0.00    0.01    0.01     0.04     0.05     8.00     0.00   23.31   1.11   0.00
dm-1              0.00     0.00    0.50   18.64    23.00   213.74    12.36     0.18    9.33   1.21   2.31

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00   321.00    0.00  337.00     0.00  5264.00    15.62     0.87    2.59   2.59  87.20
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
dm-1              0.00     0.00    0.00  658.00     0.00  5264.00     8.00     1.22    1.86   1.32  87.10

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00   315.00    0.00  345.00     0.00  5280.00    15.30     0.87    2.50   2.50  86.40
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
dm-1              0.00     0.00    0.00  660.00     0.00  5280.00     8.00     1.27    1.92   1.31  86.40

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.00   324.00    0.00  345.00     0.00  5352.00    15.51     0.86    2.50   2.50  86.10
dm-0              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
dm-1              0.00     0.00    0.00  669.00     0.00  5352.00     8.00     1.20    1.80   1.29  86.10

the query that was run to rebuild the tables was:

case 'TWN': 
        $query = "INSERT INTO Hotels.AllHotelImagesBAK (hmid, Caption, URL, Width, Height, PopOutURL, ThumbnailURL, `Default`, Source, ValidSize)
                    SELECT hmid, Caption, MainURL, Width, Height, PopOutURL, ThumbnailURL, DefaultImage, 'TWN', 'Y'
                        FROM FeedHotels.LondonTownImages 
                        INNER JOIN Hotels.HotelFeedLookup ON feedHotelID=HotelID AND feedID='TWN'
                        WHERE HotelID IN ('" . implode("','", $hotelIDs) . "')";
        break;
case 'EXP':
case 'XPP':  
        $query = "INSERT INTO Hotels.AllHotelImagesBAK (hmid, Caption, URL, Width, Height, PopOutURL, ThumbnailURL, `Default`, Source)
                    SELECT hmid, Caption, URL, Width, Height, URL, ThumbnailURL, `Default`, 'EXP' 
                        FROM FeedHotels.ExpediaImages
                        INNER JOIN Hotels.HotelFeedLookup ON feedHotelID=HotelID AND feedID='" . $feed->id . "'
                        WHERE feedHotelID IN ('" . implode("','", $hotelIDs) . "')";
        break;
case 'ORB': 
        $query = "INSERT INTO Hotels.AllHotelImagesBAK (hmid, URL, PopOutURL, ThumbnailURL, Source)
                    SELECT hmid, URL, URL, URL, 'ORB'
                        FROM FeedHotels.OrbitzImages 
                        INNER JOIN Hotels.HotelFeedLookup ON feedHotelID=HotelID AND feedID='ORB'
                        WHERE feedHotelID IN ('" . implode("','", $hotelIDs) . "')";
        break;
case 'HRS': 
        $query = "INSERT INTO Hotels.AllHotelImagesBAK (hmid, Caption, URL, Width, Height, PopOutURL, ThumbnailURL, `Default`, Source, ValidSize)
                    SELECT hmid, Location, URL, Width, Height, URL, URL, IF(`Default`='Y', 1, 0),'HRS','Y'
                        FROM FeedHotels.HRSImages 
                        INNER JOIN Hotels.HotelFeedLookup ON feedHotelID=HotelID AND feedID='HRS'
                        WHERE feedHotelID IN ('" . implode("','", $hotelIDs) . "')";
        break;
}

I am wondering what is causing this and how to solve it. Any help?

Answer 1

If the large table was reload on the Master using LOAD DATA INFILE, then here's what's happening:

• The relay logs are being used to transport the entire input file.
• The input file has to be extracted from the relay logs into a temp file.
• The Slave must execute LOAD DATA INFILE against the extracted temp file.

I have described this process in the DBA StackExchange before

• Jan 22, 2012 : MySql shell command not replicated to slave
• Apr 18, 2013 : Loading data in mysql using LOAD DATA INFILE, replication safe?
• May 04, 2014 : MySQL 5.6 showing wrong "second_behind_master"

You have to let MySQL Replication complete this process.

UPDATE 2014-09-07 15:40 EDT

I have a working theory that might uncover why relay log are growing, causing lots of write I/O, and Seconds_Behind_Master is still 0.

If your binlog_format is set to ROW or MIXED, my gut feeling is that all the rows making up the SELECT are being embedded into the relay logs in the same fashion as I described LOAD DATA INFILE, but not with the same mechanism. Why ?

LOAD DATA INFILE embeds the CSV file in binlog event chunks to allow extraction and manifestation of the CSV file in the Slave. The INSERT ... SELECT would have to treat the SELECT as a single transaction. Then, import all the row changes as part of the INSERT. In order to accomplish that, Master and Slave would have to be using binlog_format ROW or MIXED. If you were using binlog_format STATEMENT, the statement would land in the slave's relay logs instantly and the Seconds_Behind_Master would have to start climbing immediately.

This is my suspicion because of what the MySQL Documentation says about INSERT ... SELECT

Due to this issue, beginning with MySQL 5.6.4, INSERT ... SELECT ON DUPLICATE KEY UPDATE and INSERT IGNORE ... SELECT statements are flagged as unsafe for statement-based replication. With this change, such statements produce a warning in the log when using statement-based mode and are logged using the row-based format when using MIXED mode. (Bug #11758262, Bug #50439)

This takes a whole new perspective when you look at those bug reports

When MySQL 5.5.18 was released, this bug was supposed to be fixed

Bugs Fixed

• Incompatible Change: Replication: The statements in the following list are now marked as unsafe for statement-based replication. This is due to the fact that each of these statements depends on the results of a SELECT statement whose order cannot always be determined. When using STATEMENT logging mode, a warning is issued in the binary log for any of these statements; when using MIXED logging mode, the statement is logged using the row-based format.

  • INSERT ... SELECT ... ON DUPLICATE KEY UPDATE

  • REPLACE ... SELECT

  • CREATE TABLE ... IGNORE SELECT

  • CREATE TABLE ... REPLACE SELECT

  • INSERT IGNORE ... SELECT

  • UPDATE IGNORE When upgrading, you should note the use of these statements in your applications, keeping in mind that a statement that inserts or replaces rows obtained from a SELECT can take up many times as much space in the binary log when logged using row-based format than when only the statement itself is logged. Depending on the number and size of the rows selected and inserted (or replaced) by any such statements, the difference in size of the binary log after the logging of these statements is switched from statement-based to row-based can potentially be several orders of magnitude. See Section 15.1.2.1, "Advantages and Disadvantages of Statement-Based and Row-Based Replication." (Bug #11758262, Bug #50439)

Did you see that part that says

a statement that
inserts or replaces rows obtained from a SELECT can take up
many times as much space in the binary log when logged using
row-based format than when only the statement itself is
logged. Depending on the number and size of the rows selected
and inserted (or replaced) by any such statements, the
difference in size of the binary log after the logging of
these statements is switched from statement-based to row-based
can potentially be several orders of magnitude

This could be happening because you are either using a version of MySQL before 5.5.18 or a version of MySQL that missed this patch.

If you switch to binlog_format STATEMENT, this phenomenon of growing relay logs, high disk I/O, and Seconds_Behind_Master still being 0 should disappear. Either that or upgrade your MySQL.

UPDATE 2014-09-08 08:06 EDT

Let me make a clarification. Personally, I do not like binlog_format ROW because of how bloated binary and relay logs become. In this post, I said use STATEMENT. That's just my preference. The more correct for me to say is : make the Master and its Slaves have the exact same binlog_format. Just make everything MIXED. You will have to bite the bullet and resync the Slave from scratch.