KILL, and finding out what to kill takes one query.The replica is 260,000 seconds behind. That’s three days, and it has been climbing all week from the few minutes it sat at when someone first noticed.
The source is busy, and it has always been busy. It serves about 15,000 queries a second, which is what it served last month and the month before, and the write rate inside that number is flat. Nothing has been backfilled. No schema change has run, the binary logs are rotating at the rate they have for a year, and the source’s own SHOW ENGINE INNODB STATUS is clean. On the replica, the data directory is 340 GB against the source’s 84 GB, holding what is supposed to be a byte-for-byte copy of the same data.
Restarting the replica fixes it. Lag drops to zero in a few hours of catch-up, everyone moves on, and somewhere between a day and a week later the alert fires again.
It must be the applier
The first theory is throughput, and it’s the right first theory. A replica that can’t keep up with a source is usually a replica that is applying single-threaded, or applying on slower disks, or fighting the read traffic that is the whole reason it exists.
So: replica_parallel_workers raised, replica_preserve_commit_order left on, reporting traffic moved off for an afternoon, and a bigger instance class underneath. Lag kept growing. The tell that should have ended this phase early was the shape of the graph. A replica that is throughput-bound falls behind during the busy hours and gets it back in the overnight trough, so the lag line is a sawtooth. This line had no teeth. It climbed through four o’clock on Sunday morning, the quietest hours in the source’s week, at the same slope it climbed on Tuesday at noon.
Something on the replica was making every unit of work more expensive over time, and the only thing on a replica that gets monotonically more expensive over time is history.
| |
A billion. The purge pointer is sitting 1.4 billion transaction IDs behind the current counter, which is the same fact stated twice.
What the history list actually counts
InnoDB never updates a row in place for readers. An UPDATE writes the new version into the clustered index and pushes the old one into an undo log, so that any transaction with an older snapshot can still be shown the row as it looked when that snapshot began. From the manual on multi-versioning:
In the
InnoDBmulti-versioning scheme, a row is not physically removed from the database immediately when you delete it with an SQL statement.InnoDBonly physically removes the corresponding row and its index records when it discards the update undo log record written for the deletion.
Discarding those records is the purge threads’ job, and purge is not allowed to discard anything that any open read view might still need. The history list length is the count of undo log records waiting for purge. On a healthy server it sits in the thousands and bounces around as purge keeps up. It grows without limit exactly when something is holding a read view open, because purge is pinned to the oldest snapshot on the server and cannot advance past it.
Peter Zaitsev’s 2014 post on transaction history makes the distinction that matters here: there are records that can be purged and records that can’t be purged because some active transaction needs them, and a high history list is only dangerous when it’s the second kind. This was the second kind.
The cost lands on reads, and it lands in a specific place. When InnoDB walks a secondary index and finds an entry whose page has been touched by a newer transaction, it can no longer trust the index to answer the query:
When a secondary index record is delete-marked or the secondary index page is updated by a newer transaction,
InnoDBlooks up the database record in the clustered index. In the clustered index, the record’sDB_TRX_IDis checked, and the correct version of the record is retrieved from the undo log if the record was modified after the reading transaction was initiated.
A covering index stops covering. A single-row lookup becomes a clustered index descent plus a walk backwards down a version chain that is now hundreds of links long, and the manual’s own summary of where this ends is blunt: the purge thread starts to lag behind, the table grows bigger because of all the dead rows, “making everything disk-bound and very slow.”
Here is the part that took the longest to see. The replication applier is one of those readers. Every row event in the relay log has to locate its target row before it can modify it, and on a replica whose history list is in the billions, locating a row costs a chain walk. The applier slows down in proportion to the mess, the mess grows because the applier keeps writing new versions that also can’t be purged, and the source’s write rate never has to change for any of it. A steady 15,000 queries a second is all the fuel this needs. That’s why the lag climbed through the Sunday trough at the same rate it climbed at noon on a weekday.
Ask who is holding the oldest snapshot
The transaction pinning purge is visible, and it looks like nothing at all:
| |
Reproduced on a 2-million-row table on MySQL 8.0.46, with a source feeding a replica and one forgotten snapshot open on the replica, the join returns two rows:
| |
The first row is the applier, doing its job:
| |
The second row is the problem: RUNNING, zero rows modified, command Sleep, and a start time that only gets older. Look for it in SHOW ENGINE INNODB STATUS and it is not in the active list at all. A transaction that has only read holds no locks and has written no undo, so it appears in the session list as not started, which is a phrase that means something more specific than it sounds like and has cost people hours. The only evidence there is a count:
| |
One read view is all it takes. innodb_trx is the view that shows it as what it is, which is why the join above is the query to run first and SHOW ENGINE INNODB STATUS is the one that confirms the damage.
On the incident host the equivalent second row had an age_s of 1,180,000 and a host column pointing at an application server that had been terminated thirteen days earlier. A reporting request had opened a transaction, run one SELECT under REPEATABLE READ, and gone away when its process died mid-request. The connection outlived it: the pool’s keepalive had been resetting wait_timeout on a socket whose client no longer existed, so the server’s idle reaper never came for it. A transaction with nothing running in it and nothing to roll back, holding one read view, at the cost of 340 GB of undo and a replica three days behind the source it is supposed to be a copy of.
One KILL on that thread, and the history list started draining.
trx_rows_modified. A transaction showing zero has nothing to undo and disappears instantly. One showing millions will roll back when killed, single-threaded, and can hold the table hostage for longer than the original statement took to run. The safe version of this operation is to kill snapshot-holders that are idle and have modified nothing, and to escalate anything else to whoever owns the workload. Also expect purge to take real time after the kill: on a history list of a billion it is hours of IO, during which the replica is still behind and the graph is still ugly.The measurement, and what to alert on
The mechanism is easy enough to reproduce that it’s worth doing once, because the numbers make the argument better than the explanation does. A source and a replica on MySQL 8.0.46, a 2-million-row orders table, and a write workload of batched updates replaying through the applier. Run it with nothing else connected to the replica and the history list oscillates between 3 and 56 for the entire run, which is purge keeping pace. Then open a single transaction on the replica, run one SELECT, and leave it sitting there:
| |
Same source, same table, same writes. The only difference between the run that stays flat and the run that climbs is one idle connection. Then stop the write load entirely, and the interesting thing is what doesn’t happen: the history list sat at 585 and the undo tablespaces at 784 MB for as long as the snapshot stayed open, with the source completely quiet. Purge had caught up to everything it was allowed to touch and was blocked on the rest. COMMIT in the forgotten session, and the history list went to zero within a few minutes.
Two million rows is too small to show the second half of the story. Version chains a few hundred links long are still cheap to walk, so the applier in this setup never visibly slowed down; what it was throughput-bound by was the batch size, in both runs equally. The read amplification needs production scale and production time to become the dominant cost, which is exactly why the symptom arrives as lag weeks after the cause arrives as an idle connection.
The undo files are the part that surprises people who arrive at this through a disk alert rather than a lag alert. innodb_undo_log_truncate is on by default in MySQL 8.0, but an undo tablespace can only be truncated after the purge system has freed every rollback segment in it, so a pinned read view means the files grow and never shrink back to their 16 MB floor. That is where the replica’s 340 GB came from, and it’s the same class of problem as a 10 GB database filling a 200 GB disk: space held by a reference nobody remembers taking.
Two things are worth alerting on, and neither is lag. The first is trx_rseg_history_len in information_schema.innodb_metrics, which is the history list length as a number you can scrape instead of a line you have to parse out of SHOW ENGINE INNODB STATUS. It is enabled by default, unlike a lot of that table. Pick a threshold high enough never to fire on a healthy server and low enough to land a day before the lag graph moves; ten million is a reasonable place to start arguing from. The second is the age of the oldest row in information_schema.innodb_trx, with the threshold set a few minutes past the longest report the application is supposed to be able to run. Percona’s 2017 write-up of a hung transaction describes 940 transactions sitting in Sleep for 766,132 seconds and a history length past 6 million, which is the same animal at a different scale and a useful reminder that these things are usually plural.
Neither of those needs to page anyone. This is a one-lever problem with an exact signature and no judgment in it, which puts it squarely in the set that a health check bound to a watch handler can close on its own: the check goes critical on the history length, the handler runs the innodb_trx lookup, confirms trx_rows_modified is near zero, kills the thread, and files a ticket saying what it killed and how old it was. The handler pattern and the guards it needs are worth reading before wiring one, because the ticket is the load-bearing half. A handler that silently kills an abandoned transaction every few days has converted a defect in the application into a quiet maintenance routine, and the version of this incident where nobody ever finds out is the one that runs for a year.
Which is where it actually gets fixed. A transaction that begins on one request and is expected to end on the same request should be bounded by the framework, not by hope, and a connection pool that health-checks idle connections should be asking whether the session has an open transaction rather than only whether the socket answers. Neither of those is a DBA change, which is why this kind of incident tends to get fixed twice: once with a KILL at 3 a.m., and once properly, a quarter later, by whoever owns the reporting endpoint.
