It Wasn't the Load Balancer: Stale MySQL Stats After a Migration

On the evening a client's platform moved onto the cluster I'd built for it, some pages started taking five, ten, sometimes sixty seconds. The message I got was whether it could be the load balancer. Fair guess, it was the newest thing in the path. It wasn't, and the actual cause is one I'll be checking for on every migration from now on.

Clearing the load balancer

That part was quick. The pool was healthy from every location, there was no steering or session affinity sending everyone to one server, and requests were spread evenly over the three app servers.

The PHP-FPM slow log was more useful. It records a stack trace for any request that runs past five seconds, and on the first app server 93 of the 97 slow requests were sitting inside the same database call. The app servers weren't busy. They were waiting on MySQL.

The obvious fix helped, but not enough

The servers had been tested with empty databases, and the InnoDB buffer pool was still on MySQL's 128 MB default. Now there were 25 GB of real data behind it, so nearly every read went to disk. I raised it to 48 GB on all three members along with an 8 GB redo log. Both can be changed on a running server, so there was no restart and no failover, and the group stayed online the whole time.

Things got better, and I nearly left it there. The slow query log had gone quiet after a log rotation, so I flushed it and looked at what was actually slow. A lot of the queries were one shape: fetch the most recent row for a given user, ordered by id, limit one. There is an index on that user column. After the memory change the query still took around two seconds.

The optimizer thought the tables were empty

EXPLAIN showed MySQL walking the primary key of a table with about 945,000 rows instead of using the index. That only makes sense if it thinks the table is tiny, so I looked at the persistent statistics in mysql.innodb_table_stats. 86 tables said zero rows.

The statistics had been computed two days earlier, when the schema was created and the tables really were empty. Then the data was loaded, and they never caught up. MySQL is meant to recalculate them after enough of a table changes, but after a bulk import I wouldn't count on it, and here it plainly hadn't happened.

The query I use to find them now compares what the statistics claim against how big the file on disk actually is:

sql
SELECT CONCAT(s.database_name, '.', s.table_name) AS stale_table
FROM mysql.innodb_table_stats s
JOIN information_schema.innodb_tablespaces f
  ON f.name = CONCAT(s.database_name, '/', s.table_name)
WHERE s.database_name NOT IN ('mysql', 'sys')
  AND s.n_rows = 0
  AND f.file_size > 1024 * 1024;

A table that claims zero rows while its file is bigger than a megabyte is lying to the optimizer. ANALYZE TABLE on all 86 took about a fifth of a second each, and group replication carried it to the other members. The same query then used the index, looked at 29 rows and came back in under a millisecond.

Slow again, for a different reason

Just after midnight, with real users on the cluster, the client said some requests were slow again and asked whether the statistics had been refreshed. They had, and I checked again: nothing stale.

This time the slow log told a different story. For the slow queries, the lock time was the same as the query time, anywhere from 3 to 28 seconds, and the same user ids kept coming up. The application held a transaction open on a user's row while it waited on an outside service, and every other request touching that user queued behind it. That's not something the database can tune away, so I sent them the ids and timestamps and left it with their developers.

It would have been easy to go straight back to the statistics. From the outside a lock wait and a bad plan look identical, and they need opposite fixes. Now the Lock_time column is the first thing I read.

What I do after every import now

The stats query above lives in a playbook now, and I run it after every reimport, before anyone tests. It finds the stale tables and runs ANALYZE on just those. Memory gets sized for the data that's coming, not what's there on test day. And I check the slow log is really writing before trusting that it's empty, because a quiet slow log after a rotation usually means a file handle pointing at a deleted file, not a fast database.

The connection pools got suspected too, for what it's worth. MySQL was using about 30 of its 300 connections and PHP-FPM 12 of its 64 workers. Plenty of room. My guess is a lot of slowness after a migration is the database working from bad information, and that's cheap to check before buying anything bigger.

This is part of the infrastructure work I do for clients.