What causes pt-online-schema-change to slow down the further it gets through a table?

Question

I'm currently running a schema migration on a table containing ~23 million rows. The rows have a normal primary index and we're running MySQL 5.5.

The migration, to add a couple of columns, started quickly. At a rapid rate, it copied the first 3 million in about 3 minutes. The next 3 took about 20 minutes. Overnight, it did another 9 million in about 8 hours.

Other than modifying the replica lag I'm willing to accept, I've not modified the defaults - so it's obeying the chunk time and aiming to get each copy in the ~0.5 second range.

As I'm running the tool with PTDEBUG on so I can see detailed output, and it would appear the operations are correctly in that range - but I don't understand why they're getting slower and slower. At peak it was around 7000 rows a second, and it's slowly dropping further and further, we're down to ~470 now and still have ~15million rows to go.

I have several assumptions, but I'm not sure which is correct, or how to diagnose it.

Are any of my assumptions correct, and how would I identify which?

1. It's the index on the original table - the query itself is taking too long. I'm assuming it's not this, as the SELECT is off the primary key.
2. It's something to do with the insertion process. The larger the table, the more "thinking" has to be done about the INSERT and so that process is taking longer.
3. There's a hardware limitation somewhere. We're running on RDS with 3 replicas, by the way. Monitoring doesn't suggest we're hitting a bottleneck at the moment.

Here's the CREATE TABLE statement anonymised:

CREATE TABLE `user_offer` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `CreatedDate` datetime NOT NULL,
  `A` int(11) NOT NULL,
  `B` int(11) NOT NULL,
  `C` int(11) NOT NULL,
  `D` datetime DEFAULT NULL,
  `E` datetime DEFAULT NULL,
  `F` varchar(255) COLLATE utf8_unicode_ci NOT NULL,
  `G` int(11) DEFAULT NULL,
  `H` int(11) DEFAULT NULL,
  `I` int(11) NOT NULL,
  `J` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `K` tinyint(1) NOT NULL,
  `L` tinyint(1) NOT NULL,
  `M` tinyint(1) NOT NULL,
  `N` tinyint(1) NOT NULL,
  `O` int(11) NOT NULL,
  `P` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `Q` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `R` tinyint(1) NOT NULL,
  `S` tinyint(1) NOT NULL,
  `T` int(11) DEFAULT NULL,
  `U` tinyint(1) NOT NULL,
  `V` int(11) DEFAULT NULL,
  `W` datetime DEFAULT NULL,
  `X` varchar(255) COLLATE utf8_unicode_ci DEFAULT NULL,
  `Y` tinyint(1) NOT NULL,
  `Z` tinyint(1) DEFAULT NULL,
  `AA` int(11) DEFAULT NULL,
  `AB` int(11) DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `IDX_CB147C66AAB016B8` (`I`),
  KEY `IDX_CB147C6668D3EA09` (`J`),
  KEY `L_idx` (`L`),
  KEY `H_idx` (`H`),
  KEY `IDX_CB147C6632A90D98` (`T`),
  KEY `IDX_CB147C66F6CB3049` (`V`),
  KEY `createdDate_idx` (`CreatedDate`),
  KEY `consentedDate_idx` (`W`),
  CONSTRAINT `FK_CB147C6632A90D98` FOREIGN KEY (`T`) REFERENCES `table_1` (`id`),
  CONSTRAINT `FK_CB147C6668D3EA09` FOREIGN KEY (`H`) REFERENCES `table_2` (`id`),
  CONSTRAINT `FK_CB147C66AAB016B8` FOREIGN KEY (`I`) REFERENCES `table_3` (`id`),
  CONSTRAINT `FK_CB147C66F6CB3049` FOREIGN KEY (`V`) REFERENCES `table_2` (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=23448523 DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;

The alter statement is: ADD AC VARCHAR(5) plus adding indexes on AC, P and Q.

Answer 1

A guess... The Change Buffer is full and overflowing.

The operation is building 11 secondary indexes. For InnoDB, the building of secondary indexes is "delayed" by storing to-do info in a part of the buffer_pool called the Change Buffer.

Eventually the "changes" need to be flushed to disk. Your table is probably much bigger than the buffer_pool, so it is probably overflowing. Here's (roughly) how the 11 indexes for a given row are being created for the new table:

• Write 11 records to the Change Buffer. Such a record is (I guess) the secondary key column(s) plus the primary key column(s).
• Check for overflow. If running out of room (which you are by now), read some index block from disk, fold the index entries into it, queue the block for writing back to disk, and free up the index entries from the Change Buffer.

Initially all 11 indexes were empty, so the above process was dumping blocks full of stuff out to disk -- very efficient.

As the processing continues, the indexes get bigger, and the "dumping of more entries" becomes less efficient because there are more blocks to deal with and few records to put in each one. That is, each read-modify-write step is freeing up fewer and fewer entries from the Change Buffer.

This feeds back to slowing down the processing, which pt-online-schema-change smartly turns into smaller chunk sizes.

Alternatives

• It is sometimes better to rebuild indexes after building the table. However, you probably don't want to because it would involve downtime.

• In 5.6 (and more in 5.7), many ALTERs can be performed with very little impact on the running system. 5.5 is now the oldest supported version; you should consider upgrading. (Pt-online-schema-change is still be useful for cases where online alters do not apply.)

• Vertical partitioning -- Instead of adding columns to this table, you could have considered building a 'parallel' table with the new columns. This can usually be done with no downtime. Although some SELECTs will need a JOIN, this is not necessarily a performance burden.

Answer 2

We managed to complete the migration after making one change: We were using a magnetic disk for our RDS instance, and we migrated to SSDs.

Clues from both this comment by akuzminsky and from Rick James' answer pointed towards that - and the real clue should have been Read Latency in AWS monitoring, which was pointing out that more and more reads were waiting longer and longer to fulfill - sometimes almost a minute.

The upgrade to SSD solved the problem. In the first attempt(s) we started at 7000 ish reads per second, which slowly dropped to around 100 / second at the halfway point before dying shortly after that.

After the upgrade to SSD, the reads / sec started at around 10,000 and dropped to around 5,5000 at the half way point before finishing at around 1200 / sec.

Furthermore this has lead to a small but consistent improvement across the board in performance.

We intend to upgrade to 5.6 or 5.7 to help solve the longer term problem, and will be looking at the answer from Rick in detail for inspiration later.