A CPU-saturated MySQL server: full scans, long procedures and idle transactions

A manufacturer of windows, doors and related products ran its main database on one physical MySQL server that was using all of its CPU. About a thousand connections were open and almost all of them were idle. The server had nearly eleven thousand accounts. Disk I/O was light. A statement log of 19.37 million statements had no single dominant query: the most expensive fingerprint was 8.1% of execution time, and the top ten together were 43.7%. The long work was full scans and a few stored procedures. Separate samples showed transactions left idle while they still held row locks.

Table and column names below are renamed to describe what the tables hold. Counter values in the MySQL summary are fuzzy-rounded, as the report states.

The starting point

The machine was a physical server, not a virtual machine, which the report treated as the right default: virtualisation is another source of overhead unless its advantages justify the cost. It had one Xeon, six cores with hyperthreading (12 logical CPUs), and 126 GB of RAM. At the OS summary the load average was 22.91, 20.14, 18.06. mysqld was the only substantial process and was using about 1,183% of one CPU and 97 GB of resident memory.

vmstat during the collection showed the same picture. In the busy samples, user CPU was 96–99%, iowait was 0, and about 25–30 processes were runnable. The report’s conclusion was that the CPU was heavily loaded and the I/O was not.

The status counters describe a server that reads a great many rows and writes comparatively little:

• About 1,250 statements/s on average since start, and about 2,500/s during an 11-second sample. MySQL had been up for about 16 hours, so the lifetime rates are a short baseline. The statement log, collected separately from those counters, recorded 661 statements/s and 4.87× concurrency.
• Reads dominate the row counters. InnoDB reported about 5 million rows read per second on average, and about 15 million/s during the sample. On average, rows inserted were about 1,000/s, updated about 100/s and deleted about 50/s.
• The access method was a scan. Handler_read_rnd_next (a table scan) was about 4 million/s on average and about 15 million/s in the sample. Handler_read_next (an index scan) was about 800,000/s. The report called these, in that order, the least efficient ways to read rows.
• Disk was quiet. InnoDB did about 70 reads/s from disk on average (about 60 of them buffer-pool misses) and only a handful per second during the sample. Data writes were about 125/s on average and about 150/s in the sample, with about 50–90 redo-log writes/s. The report said a small RAID of spinning disks should cope, and that a single spinning disk was the arrangement that might not.
• About 1,000 connections, about 25 of them running, roughly 20 of those in Sending data. New connections were about 2/s in the sample, so sessions were opened and then left up. Aborted_connects was about 80/day, so authentication was not the problem. Aborted_clients was about 7,000/day, which the report read as connections dropped by a timeout rather than closed.

Most statements in the log were short. Across 19.37 million statements the median execution time was 119 µs, the 95th percentile was 1 ms and the average was 7 ms, with a maximum of 7,179 s. Total execution time was 142,805 s. Total lock time in the same log was 17,085 s (maximum 2,176 s, median 21 µs). The global InnoDB counters agreed that lock waits were not the bulk of the load: about 8,000 row-lock waits over a day, and about 90 ms of row-lock wait accumulated per second. The report called that negligible. The pt-stalk samples, taken separately, still showed individual transactions holding locks for minutes. Both observations are in the report.

The statement mix from Com_* needs the report’s caveat. The application mostly used prepared statements (about 800 Com_stmt_execute/s on average, about 2,250/s in the sample). A MySQL bug of that version also increments the matching Com_select, Com_delete and similar counters for a prepared statement, so those rates may be double-counted. With that caveat, the report read the lifetime counters as DELETE about 450/s, SELECT about 350/s, UPDATE about 50/s and INSERT about 25/s, and said the main traffic was modifications. During the 11-second sample the same counters showed SELECT at about 2,000/s, UPDATE about 100/s, INSERT about 90/s and DELETE about 20/s. The InnoDB row counters above are the clearer evidence that the server spent its time reading.

Finding 1: ten fingerprints, none of them most of the load

The log was grouped by fingerprint and ranked by total execution time. The top fingerprint was 8.1%, the next 8.0%, the next 5.0%. The report noted that a top ten of 43.7% is lower than usual, which means the load was spread across many statements rather than one.

Three fingerprints were the same customer listing, with small differences in the filter. It selected customers, and for each one ran correlated subqueries: a warning lookup, a count of recent orders joined back to customers, and an age calculation against a recent-customers table. The captured form also excluded codes with NOT IN (SELECT DISTINCT code FROM …).

SELECT …
  FROM customers c
 WHERE c.code NOT IN (SELECT DISTINCT code FROM excluded_customers)
 ORDER BY …;

The customer-listing index, and the same treatment of its two sibling fingerprints, was something the report asked to have checked for feasibility. The finance indexes, the station index, the record-number index and the two indexes in the last rows were concrete ALTER TABLE statements. The discount comparison and the IN-list rewrite were to be implemented. Every index was to be tried on a test system first, so a side effect would show up there rather than in production.

The flag update was a one-row change by a record number that scanned the table. added is the column the statement set:

UPDATE event_log SET added = 1 WHERE record_no = …;

ALTER TABLE event_log ADD KEY idx_record_no (record_no);

The order-line UNION repeated a discount lookup of the form WHERE order_no LIKE …. Written as WHERE order_no = …, the same lookup can use an index. The report did not add a new index for that query. It removed the predicate that prevented the existing one from being used.

Finding 2: transactions left open, holding locks

The global counters said lock waits were a small part of the server’s time. The pt-stalk samples showed how a single idle transaction could still block one statement for a long time. In each example the blocking transaction’s current statement was NULL and the connection was Sleep.

• A multi-table DELETE had been waiting 51 s. The transaction it waited on had started about 80 s earlier, held locks on 9,905 rows, and had modified 4,886 of them. It was not running a statement.
• An INSERT of one wide row had been waiting 12 s. The blocker held locks on 168 rows, had modified 49, and had been open for about 13 s. It was idle.
• Other transactions were idle with locks still held: one open for about 6 minutes with 200 rows locked and none modified; one for about 7 minutes with about 17,600 rows locked and 8,795 modified; one for about 18 minutes with 26 rows locked and 8 modified.

A second pattern was two statements locking overlapping rows. Two UPDATEs changed status and a progress percentage on the same planning table. Their WHERE clauses named different codes, and the second waited for the first. The report’s reading was that the predicate did not isolate the row set tightly enough, or that the locked ranges overlapped, with the same result either way.

The high-priority recommendation attached to this section was not a configuration change. It was to look at this access pattern and consider a different way in: one application in front of the database, instead of hundreds of connections left open. That is the same theme as the account list below.

Finding 3: thousands of accounts, and what was already set well

The instance held 46 schemas. It had 10,986 accounts: 2 anonymous, 6 with no password and 6 using the old password hash. At the sample, connections came from many accounts and many hosts. The busiest account held on the order of 175 connections. Most of the others held one connection or a few, under 9. One schema held about 900 of the roughly 1,000 connections. The report asked whether every account had full access to the data and whether that access was necessary, including as a security question.

On performance, the report’s point was concurrency. An idle connection still costs something. The machine can usefully run about 6 to 12 queries at once, because a hyperthread is not as capable as a physical core, and every query beyond that slows the others. An application can protect the database in a way that direct accounts cannot, for example by running short transactional statements first and queueing analytical ones. The report did not claim to know how access was organised; it said the current shape was the wrong default.

Much of the configuration was already what the report would have chosen, and was left alone:

• The query cache was off. At this concurrency it would have serialised statements on its mutex.
• innodb_file_per_table was on. Checksums, the doublewrite buffer and XA support were on.
• innodb_flush_log_at_trx_commit=1, so a committed transaction survives a crash of the server or of InnoDB. The report noted that this increases writes, and that a RAID controller with a working write-back cache would keep that cost down. The cache mode was not visible: the RAID management software was not installed, so the report could not see the RAID level or the battery. Its general guidance, not an observation, was RAID 1 or RAID 10, write-back when the battery is healthy, and read-ahead on spinning disks more than on SSDs.
• Redo logs were 2 × 2 GB. The 16 MB log buffer looked large, but the report left it: large log files are not themselves a problem, and the write rate was not measured finely enough to resize the buffer.
• The default isolation level was REPEATABLE READ. The report considered that fine for most of this workload.
• Adaptive flushing was on. The checkpoint age was 407 MB, which the report read as InnoDB keeping up with a modest write rate.
• join_buffer_size was at the default. tmp_table_size was 128 MB and max_heap_table_size was 16 MB, which looked right. Temporary tables were not a large cost: about 15/s created, about 1/s on disk.
• The thread cache was large enough. Threads_created over the uptime was about 2,000, and new threads were not showing up as a rate.
• There were no table-lock waits during the collection.
• Transparent huge pages were enabled, which the report called the right setting in most cases.
• The filesystem was ext4. The network had no interface errors. Four gigabit ports were bonded and reported at 4 Gb/s, full duplex. The report called the bond a good idea provided the links also land on separate switches.

The changes it did want, outside the SQL:

The root filesystem was a 1.6 TB ext4 volume at 91% full. The report made this high priority, and it did not guess a date: estimate the growth from the history so far, and plan the move to a larger disk before the volume fills.

The recommendations, in order

The report’s own order is below. Anything that needs a restart can wait for a planned one: none of those items was urgent. Anything that adds an index goes to a test system first.

1. Check whether the customer-listing changes are possible: pull the dependent subqueries out, pass the exclusion list in as values, and add the index on the recent-customers code. The two related fingerprints get the same treatment.
2. Add the five indexes used by the daily finance procedure.
3. Check the search procedure: the station index, and a client lookup that can use the index on client code.
4. Index the record number on the log table the flag update scans.
5. Change the discount lookup in the order-line UNION from LIKE to =.
6. On the batch lookup, add (code, line) and build the IN list outside the statement.
7. Index the workstation column used by the import procedure.
8. Review the idle transactions, and consider one application in front of the database instead of thousands of accounts and hundreds of open connections. High priority.
9. Estimate when the 91% full root filesystem needs a larger disk. High priority.
10. Upgrade to the latest MySQL 5.6. High priority.
11. Upgrade the kernel, or confirm that security fixes are backported. Medium priority.
12. Find why connections are dropped on timeout. Medium priority.
13. At low priority: benchmark SELinux, add 10 GB to the buffer pool only if memory use is stable, set swappiness to 1, switch the scheduler to noop, raise the table cache to 1,024, and test O_DIRECT.

The report also suggested raising innodb_io_capacity to 600–800 if the disks can sustain it, trying innodb_thread_concurrency=24, testing binlog_format=ROW against the extra log volume, converting production MyISAM tables to InnoDB, and reviewing the enlarged session buffers. Those were not in the summary priority list.

The recent-order count (3.3% of execution time) is absent from this list because the report found nothing to change.

What this case shows

The limiting resource was CPU. Disk throughput had headroom, and the global lock counters were small: about 90 ms of row-lock wait accumulated per second. The statement log explains the CPU. Most statements were short. The time that was long was spread across scans and a handful of procedures, several of them measuring in the thousands of seconds and billions of rows. The fixes named for those were indexes, a LIKE turned into an equality, and correlated subqueries pulled out of the statement so the application could do the last step.

The samples add a second fact the averages hide. A transaction that has modified thousands of rows and then gone idle still holds its locks, and the next statement on those rows waits for as long as that transaction stays open. Together with nearly eleven thousand accounts and about a thousand connections, that is why the report’s high-priority item next to the SQL was the way the database was reached, not another buffer size.

The audit does not show what happened after the changes. It says which changes to test, which to make, and which to leave for a planned restart.