A read replica that was silently stale

A customer placed an order, was shown a confirmation, refreshed the page and saw an empty order history. Support could see the order. The customer could not. Both were reading the same application, and one of them was reading a replica that was fifty-one minutes behind and reporting itself healthy.

The symptom

mysql> SHOW SLAVE STATUSG
         Slave_IO_Running: Yes
        Slave_SQL_Running: Yes
    Seconds_Behind_Master: 0
   Last_SQL_Error:

mysql> SELECT MAX(placed_at) FROM orders;
2020-06-14 09:41:02

mysql> SELECT NOW();
2020-06-14 10:32:18

-- fifty-one minutes. and every status field says fine.

Both threads running, no error, zero seconds behind, and an hour of missing data. Nothing in that output is a lie — the fields mean something other than what everybody reads them as.

Why it happens

Slave_IO_Running       is it RECEIVING events from the primary?
Slave_SQL_Running      is it APPLYING the events it has?
Seconds_Behind_Master  how far behind the events it HAS.

all three were fine because the replica had received
everything and applied everything it had received.

what it had received was one statement: an ALTER TABLE that
had been running for fifty-one minutes, blocking every event
behind it in the relay log.

Seconds_Behind_Master is computed from the timestamp of the event currently being processed. During a long-running statement there is no newer event to compare against, so the field reports zero for as long as the statement runs — which is the case where the number matters most.

The same happens during a network partition where the IO thread is stalled but not errored, and after a replica restart before the first event arrives. In all three the field is honest about a question nobody was asking.

The fix

A heartbeat table, which is the only honest measurement

-- on the primary
CREATE TABLE heartbeat (
  id TINYINT UNSIGNED NOT NULL PRIMARY KEY,
  ts DATETIME(6) NOT NULL
) ENGINE=InnoDB;

-- every second, from a timer on the primary
REPLACE INTO heartbeat (id, ts) VALUES (1, NOW(6));

-- on the replica: wall-clock staleness, end to end
SELECT TIMESTAMPDIFF(MICROSECOND, ts, NOW(6)) / 1000 AS lag_ms
FROM heartbeat WHERE id = 1;

This measures the thing the application cares about: how old is the newest data I can see. It cannot be fooled by a long statement, a stalled thread or a restart, because the row simply stops being updated and the difference grows.

The clocks have to agree, which means NTP on both hosts and a check that it is running — a replica with a clock two minutes fast reports negative lag, which is at least obviously wrong. pt-heartbeat does this properly and handles the chained-replica case; the four lines above are enough for one level.

Read-after-write, and the connection that must be the primary

// config/database.php
'mysql' => [
    'read'   => ['host' => ['10.0.2.11', '10.0.2.12']],
    'write'  => ['host' => ['10.0.2.10']],
    'sticky' => true,
],

// sticky: after ANY write in this request, subsequent reads
// on this connection go to the primary.
//
// and what it does NOT cover:
//   a queue job dispatched by that request
//   a second request from the same user, milliseconds later
//   anything on a different connection

Sticky mode covers the common case automatically and covers it per request, which is why the confirmation page was correct and the refresh was not — a new request has no memory of the write. That gap is the one that produced the incident, and no connection-level setting closes it.

// the explicit form, for the reads that must be current
$order = Order::onWriteConnection()->findOrFail($id);

// and for a whole block
DB::connection('mysql')->beginTransaction();   // forces the primary

// the queue case, which is the one everybody misses
class SendReceipt implements ShouldQueue
{
    public function handle(): void
    {
        $order = Order::onWriteConnection()->find($this->orderId);

        if ($order === null) {
            $this->release(5);      // dispatched before commit

            return;
        }
    }
}

The queue case is the one that produces the most confusing bugs: the job runs on another machine seconds later, has no sticky state, and reads a replica that may not have the row. The release-and-retry is the belt to the primary-read braces — a job dispatched inside an uncommitted transaction finds nothing on any connection, and waiting five seconds is cheaper than reasoning about transaction boundaries at every dispatch site.

Routing per query, and the default that is dangerous

the rule that survives contact with a codebase:

  a read that follows a write in the same user action  → primary
  a read whose result the user just caused             → primary
  a listing, a search, a report, a dashboard           → replica
  anything inside a transaction                        → primary
                                                          (automatic)

and the decision belongs in the repository method, once,
rather than at each call site.

Putting the decision in a named repository method rather than at the call site is what makes it reviewable — Orders::findForConfirmation() reads on the primary and Orders::listForCustomer() does not, and the names carry the reasoning. Scattering onWriteConnection() through controllers produces a codebase where nobody can tell which reads are safe.

The dangerous part is that the default is the fast one. A new query written next week goes to a replica unless somebody thought about it, and the failure is intermittent and load-dependent — which is why this is a permanent tax on writing code rather than a migration that finishes.

Taking a lagging replica out of the pool

#!/usr/bin/env bash
set -euo pipefail

for host in 10.0.2.11 10.0.2.12; do
  lag=$(mysql -h "$host" -Nse 
    'SELECT TIMESTAMPDIFF(SECOND, ts, NOW()) FROM heartbeat WHERE id=1')

  io=$(mysql -h "$host" -Nse 'SHOW SLAVE STATUSG' 
       | awk '/Slave_IO_Running/{print $2}')

  if [ "$lag" -gt 5 ] || [ "$io" != "Yes" ]; then
    consul kv put "replica/$host/enabled" false
  else
    consul kv put "replica/$host/enabled" true
  fi
done

Something has to act on the measurement or the heartbeat is a dashboard. Whatever holds the replica list — a service registry, a proxy configuration, an application config reloaded periodically — needs to read this, and wiring that up is most of the work.

The threshold is a product decision disguised as a number: five seconds of staleness is invisible on a report and unacceptable on an order history. Setting it from the tightest requirement any replica read has is the conservative choice and means the replicas are removed more often than strictly necessary.

What the replica was actually for

It is worth asking, once the cost is visible, whether the replica was solving the problem it was added for — because on this system it largely was not.

why it was added, in 2018:
  "the database CPU is at 80% and reads are most of it"

what the reads actually were, measured:
  61%  the same twelve queries, on every page load
  22%  a nightly report, running at 02:00
  17%  everything else

the 61% was a missing cache. the 22% did not need to be
on the primary and never had. only the 17% was the case
a replica exists for.

Caching the twelve queries took the primary from 80% to 34% and would have removed the need for the replica entirely — which is not an argument against replicas so much as an argument for measuring before adding infrastructure. The replica had been the first answer because it is the answer everybody knows.

The replica stayed, because by then it was also the failover target and the place the nightly report ran, and both of those are good reasons. The point is that it was justified after the fact rather than before, and the read-routing tax was paid for two years to solve a problem a cache would have solved in an afternoon.

The alert that would have caught this

- alert: ReplicaLagging
  expr: mysql_heartbeat_lag_seconds > 5
  for: 2m
  labels: { severity: page }
  annotations:
    summary: "{{ $labels.instance }} is {{ $value }}s behind"
    description: |
      Reads may be stale. Check, in order:
        1. a long-running statement — SHOW PROCESSLIST on the replica
        2. the IO and SQL threads
        3. disk or network saturation on the replica
      Do NOT restart replication. It will not help and loses the position.

- alert: ReplicaThreadStopped
  expr: mysql_slave_sql_running == 0 or mysql_slave_io_running == 0
  for: 1m
  labels: { severity: page }

Both alerts are needed and they catch different things: a stopped thread is usually a duplicate key or a network problem and is loud, and growing lag with both threads healthy is a slow statement and is silent. The original incident produced neither alert because neither existed.

Verifying it worked

# a deliberately delayed replica, on staging
mysql> STOP SLAVE;
mysql> CHANGE MASTER TO MASTER_DELAY = 10;
mysql> START SLAVE;

$ php artisan test --group=replication

 ✓ an order is visible immediately after being placed
 ✓ the receipt job finds the order it was told about
 ✗ the order history shows a just-placed order
   Failed asserting that an array contains 91204.

# which is the bug, reproduced in a test, for the first time.

A ten-second artificial delay turns an intermittent production bug into a deterministic test failure, which is the single most valuable thing in this whole exercise — the class of bug that only appears under load is now caught by the suite. Running that group nightly rather than on every push keeps it affordable.

# and in production, a fortnight later
#   heartbeat lag p99:        0.9s
#   longest observed:        41s  (an ALTER, during a release)
#   replica removed from pool: yes, automatically, for 43s
#   customer-visible effect:  none

# the same ALTER, before this work: fifty-one minutes of
# silently stale reads.

What this costs

A decision per query, permanently, with a dangerous default. Every new read is implicitly routed to a replica and the consequence of getting it wrong is invisible in development, invisible in testing, and intermittent in production. The repository-method discipline helps and does not remove it — this is a tax that a read replica charges forever, and it is worth stating when the replica is first proposed rather than discovering it a year later.

The other cost is a new failure mode that is not “down”. A replica that is up, accepting connections and serving hour-old data is worse than one that has crashed, because everything routes to it happily and the symptom appears somewhere else entirely — in this case as a customer support ticket about a missing order. Monitoring that treats “responding” as “healthy” will never catch it, and that is true of a great many things beyond replicas.