MySQL Adventures: How max_prepared_stmt_count can bring down production

We recently moved an On-Prem environment to GCP for better scalability and availability. The customer’s main database is MySQL. Due to the nature of customer’s business, it’s a highly transactional workload (one of the hot startups in APAC). To deal with the scale and meet availability requirements, we have deployed MySQL behind ProxySQL — which takes care of routing some of the resource intensive SELECTs to chosen replicas. The setup consists of:

  • One Master
  • Two slaves
  • One Archive database server

Post migration to GCP, everything was nice and calm for a couple of weeks, until MySQL decided to start misbehaving and leading to an outage. We were able to quickly resolve and bring the system back online and what follows are lessons from this experience.

The configuration of the Database:

  • CentOS 7.
  • MySQL 5.6
  • 32 Core CPU
  • 120GB Memory
  • 1 TB SSD for MySQL data volume.
  • The total database size is 40GB. (yeah, it is small in size, but highly transactional)
  • my.cnf is configured using Percona’s configuration wizard.
  • All tables are InnoDB Engine
  • No SWAP partitions.

The Problem

It all started with an alert that said MySQL process was killed by Linux’s OOM Killer. Apparently MySQL was rapidly consuming all the memory (about 120G) and OOM killer perceived it as a threat to the stability of the system and killed the process. We were perplexed and started investigating.

Sep 11 06:56:39 mysql-master-node kernel: Out of memory: Kill process 4234 (mysqld) score 980 or sacrifice child
Sep 11 06:56:39 mysql-master-node kernel: Killed process 4234 (mysqld) total-vm:199923400kB, anon-rss:120910528kB, file-rss:0kB, shmem-rss:0kB
Sep 11 06:57:00 mysql-master-node mysqld: /usr/bin/mysqld_safe: line 183:  4234 Killed   nohup /usr/sbin/mysqld --basedir=/usr --datadir=/mysqldata --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --open-files-limit=65535 --pid-file=/var/run/mysqld/mysqld.pid --socket=/mysqldata/mysql.sock < /dev/null > /dev/null 2>&1

Naturally, we started looking at mysql configuration to see if something is off.

InnoDB Parameters:

innodb-flush-method            = O_DIRECT
innodb-log-files-in-group = 2
innodb-log-file-size = 512M
innodb-flush-log-at-trx-commit = 1
innodb-file-per-table = 1
innodb-buffer-pool-size = 100G

Other Caching Parameters:

tmp-table-size                 = 32M
max-heap-table-size = 32M
query-cache-type = 0
query-cache-size = 0
thread-cache-size = 50
open-files-limit = 65535
table-definition-cache = 4096
table-open-cache = 50

We are not really using query cache and one of the heavy front end service is PHP Laravel.

Here is the memory utilization graph.

The three highlighted areas are the points at which we had issues in production. The second issue happened very shortly, so we reduced the innodb-buffer-pool-size to 90GB. But even though the memory utilization never came down. So we scheduled a cronjob to flush OS Cache at least to give some addition memory to the Operating system by using the following command. This was a temporary measure till we found the actual problem.

sync; echo 3 > /proc/sys/vm/drop_cache

But This didn’t help really. The memory was still growing and we had to look at what’s really inside the OS Cache?

Fincore:

There is a tool called fincore helped me find out what’s actually the OS cache held. Its actually using Perl modules. use the below commands to install this.

yum install perl-Inline
rpm -ivh http://fr2.rpmfind.net/linux/dag/redhat/el6/en/x86_64/dag/RPMS/fincore-1.9-1.el6.rf.x86_64.rpm

It never directly shows what files are inside the buffer/cache. We instead have to manually give the path and it’ll check what files are in the cache for that location. I wanted to check about Cached files for the mysql data directory.

cd /mysql-data-directory
fincore -summary * > /tmp/cache_results

Here is the sample output of the cached files results.

page size: 4096 bytes
auto.cnf: 1 incore page: 0
dbadmin: no incore pages.
Eztaxi: no incore pages.
ibdata1: no incore pages.
ib_logfile0: 131072 incore pages: 0 1 2 3 4 5 6 7 8 9 10......
ib_logfile1: 131072 incore pages: 0 1 2 3 4 5 6 7 8 9 10......
mysql: no incore pages.
mysql-bin.000599: 8 incore pages: 0 1 2 3 4 5 6 7
mysql-bin.000600: no incore pages.
mysql-bin.000601: no incore pages.
mysql-bin.000602: no incore pages.
mysql-bin.000858: 232336 incore pages: 0 1 2 3 4 5 6 7 8 9 10......
mysqld-relay-bin.000001: no incore pages.
mysqld-relay-bin.index: no incore pages.
mysql-error.log: 4 incore pages: 0 1 2 3
mysql-general.log: no incore pages.
mysql.pid: no incore pages.
mysql-slow.log: no incore pages.
mysql.sock: no incore pages.
ON: no incore pages.
performance_schema: no incore pages.
mysql-production.pid: 1 incore page: 0
6621994 pages, 25.3 Gbytes in core for 305 files; 21711.46 pages, 4.8 Mbytes per file.
The highlighted points show the graph when OS Cache is cleared.

How we investigated this issue:

The first document that everyone refers is How mysql uses the memory from MySQL’s documentation. So we started with where are all the places that mysql needs memory. I’ll explain this about in a different blog. Lets continue with the steps which we did.

Make sure MySQL is the culprit:

Run the below command and this will give you the exact memory consumption about MySQL.

ps --no-headers -o "rss,cmd" -C mysqld | awk '{ sum+=$1 } END { printf ("%d%s\n", sum/NR/1024,"M") }'
119808M

Additional Tips:

If you want to know each mysql’s threads memory utilization, run the below command.

# Get the PID of MySQL:
ps aux | grep mysqld
mysql     4378 41.1 76.7 56670968 47314448 ?   Sl   Sep12 6955:40 /usr/sbin/mysqld --basedir=/usr --datadir=/mysqldata --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --open-files-limit=65535 --pid-file=/var/run/mysqld/mysqld.pid --socket=/mysqldata/mysql.sock
# Get all threads memory usage:
pmap -x 4378
4378:   /usr/sbin/mysqld --basedir=/usr --datadir=/mysqldata --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysqld.log --open-files-limit=65535 --pid-file=/var/run/mysqld/mysqld.pid --socket=/mysqldata/mysql.sock
Address Kbytes RSS Dirty Mode Mapping
0000000000400000 11828 4712 0 r-x-- mysqld
000000000118d000 1720 760 476 rw--- mysqld
000000000133b000 336 312 312 rw--- [ anon ]
0000000002b62000 1282388 1282384 1282384 rw--- [ anon ]
00007fd4b4000000 47816 37348 37348 rw--- [ anon ]
00007fd4b6eb2000 17720 0 0 ----- [ anon ]
00007fd4bc000000 48612 35364 35364 rw--- [ anon ]
.........
.........
.........
00007fe1f0075000 2044 0 0 ----- libpthread-2.17.so
00007fe1f0274000 4 4 4 r---- libpthread-2.17.so
00007fe1f0275000 4 4 4 rw--- libpthread-2.17.so
00007fe1f0276000 16 4 4 rw--- [ anon ]
00007fe1f027a000 136 120 0 r-x-- ld-2.17.so
00007fe1f029c000 2012 2008 2008 rw--- [ anon ]
00007fe1f0493000 12 4 0 rw-s- [aio] (deleted)
00007fe1f0496000 12 4 0 rw-s- [aio] (deleted)
00007fe1f0499000 4 0 0 rw-s- [aio] (deleted)
00007fe1f049a000 4 4 4 rw--- [ anon ]
00007fe1f049b000 4 4 4 r---- ld-2.17.so
00007fe1f049c000 4 4 4 rw--- ld-2.17.so
00007fe1f049d000 4 4 4 rw--- [ anon ]
00007ffecc0f1000 132 72 72 rw--- [ stack ]
00007ffecc163000 8 4 0 r-x-- [ anon ]
ffffffffff600000 4 0 0 r-x-- [ anon ]
---------------- ------- ------- -------
total kB 122683392 47326976 47320388

InnoDB Buffer Pool:

Initially we suspected the InnoDB. We have checked the innoDB usage from the monitoring system. But the result was negative. It never utilized more than 40GB. That thickens the plot. If buffer pool only has 40 GB, who is eating all that memory?

Is this correct? Does Buffer Pool only hold 40GB?

What’s Inside the BufferPool and whats its size?

SELECT
page_type AS page_type,
sum(data_size) / 1024 / 1024 AS size_in_mb
FROM
information_schema.innodb_buffer_page
GROUP BY
page_type
ORDER BY
size_in_mb DESC;
+-------------------+----------------+
| Page_Type | Size_in_MB |
+-------------------+----------------+
| INDEX | 39147.63660717 |
| IBUF_INDEX | 0.74043560 |
| UNDO_LOG | 0.00000000 |
| TRX_SYSTEM | 0.00000000 |
| ALLOCATED | 0.00000000 |
| INODE | 0.00000000 |
| BLOB | 0.00000000 |
| IBUF_BITMAP | 0.00000000 |
| EXTENT_DESCRIPTOR | 0.00000000 |
| SYSTEM | 0.00000000 |
| UNKNOWN | 0.00000000 |
| FILE_SPACE_HEADER | 0.00000000 |
+-------------------+----------------+

A quick guide about this query.

  • INDEX: B-Tree index
  • IBUF_INDEX: Insert buffer index
  • UNKNOWN: not allocated / unknown state
  • TRX_SYSTEM: transaction system data

Bonus:

To get the buffer pool usage by index

SELECT
table_name AS table_name,
index_name AS index_name,
count(*) AS page_count,
sum(data_size) / 1024 / 1024 AS size_in_mb
FROM
information_schema.innodb_buffer_page
GROUP BY
table_name, index_name
ORDER BY
size_in_mb DESC;

Then where mysql was holding the Memory?

We checked all of the mysql parts where its utilizing memory. Here is a rough calculation for the memory utilization during the mysql crash.

BufferPool: 40GB
Cache/Buffer: 8GB
Performance_schema: 2GB
tmp_table_size: 32M
Open tables cache for 50 tables: 5GB
Connections, thread_cache and others: 10GB

Almost it reached 65GB, we can round it as 70GB out of 120GB. But still its approximate only. Something is wrong right? My DBA mind started to think where is the remaining?

Till now,

  1. MySQL is the culprit who is consuming all of the memory.
  2. Clearing OS cache never helped. Its fine.
  3. Buffer Pool is also in healthy state.
  4. Other memory consuming parameters are looks good.

It’s time to Dive into the MySQL.

Lets see what kind of queries are running into the mysql.

show global status like 'Com_%';
+---------------------------+-----------+
| Variable_name | Value |
+---------------------------+-----------+
| Com_admin_commands | 531242406 |
| Com_stmt_execute | 324240859 |
| Com_stmt_prepare | 308163476 |
| Com_select | 689078298 |
| Com_set_option | 108828057 |
| Com_begin | 4457256 |
| Com_change_db | 600 |
| Com_commit | 8170518 |
| Com_delete | 1164939 |
| Com_flush | 80 |
| Com_insert | 73050955 |
| Com_insert_select | 571272 |
| Com_kill | 660 |
| Com_rollback | 136654 |
| Com_show_binlogs | 2604 |
| Com_show_slave_status | 31245 |
| Com_show_status | 162247 |
| Com_show_tables | 1105 |
| Com_show_variables | 10428 |
| Com_update | 74384469 |
+---------------------------+-----------+

Select, Insert, Update these counters are fine. But a huge amount of prepared statements were running into the mysql.

One more Tip: Valgrind

Valgrind is a powerful open source tool to profile any process’s memory consumption by threads and child processes.

Install Valgrind:

# You need C compilers, so install gcc
wget ftp://sourceware.org/pub/valgrind/valgrind-3.13.0.tar.bz2
tar -xf valgrind-3.13.0.tar.bz2
cd valgrind-3.13.0
./configure
make
make install
Note: Its for troubleshooting purpose, you should stop MySQL and Run with Valgrind.
  • Create an log file to Capture
touch /tmp/massif.out
chown mysql:mysql /tmp/massif.out
chmod 777 /tmp/massif.out
  • Run mysql with Valgrind
/usr/local/bin/valgrind --tool=massif --massif-out-file=/tmp/massif.out /usr/sbin/mysqld –default-file=/etc/my.cnf
  • Lets wait for 30mins (or till the mysql takes the whole memory). Then kill the Valgranid and start mysql as normal.

Analyze the Log:

/usr/local/bin/ms_print /tmp/massif.out

We’ll explain mysql memory debugging using valgrind in an another blog.

Memory Leak:

We have verified all the mysql parameters and OS level things for the memory consumption. But no luck. So I started to think and search about mysql’s memory leak parts. Then I found this awesome blog by Todd.

Yes, the only parameter I didn’t check is max_prepared_stmt_count.

What is this?

From MySQL’s Doc,

This variable limits the total number of prepared statements in the server. It can be used in environments where there is the potential for denial-of-service attacks based on running the server out of memory by preparing huge numbers of statements.
  • Whenever we prepared a statement, we should close in the end. Else it’ll not the release the memory which is allocated to it.
  • For executing a single query, it’ll do three executions (Prepare, Run the query and close).
  • There is no visibility that how much memory is consumed by a prepared statement.

Is this the real root cause?

Run this query to check how many prepared statements are running in mysql server.

mysql> show global status like 'com_stmt%';
+-------------------------+-----------+
| Variable_name | Value |
+-------------------------+-----------+
| Com_stmt_close | 0 |
| Com_stmt_execute | 210741581 |
| Com_stmt_fetch | 0 |
| Com_stmt_prepare | 199559955 |
| Com_stmt_reprepare | 1045729 |
| Com_stmt_reset | 0 |
| Com_stmt_send_long_data | 0 |
+-------------------------+-----------+

You can see there are 1045729 prepared statements are running and the Com_stmt_close variables is showing none of the statements are closed.

This query will return the max count for the preparements.

mysql> show variables like 'max_prepared_stmt_count';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| max_prepared_stmt_count | 1048576 |
+-------------------------+---------+

Oh, its the maximum value for this parameter. Then we immediately reduced it to 2000.

mysql> set global max_prepared_stmt_count=2000;
-- Add this to my.cnf
vi /etc/my.cnf
[mysqld]
max_prepared_stmt_count = 2000

Now, the mysql is running fine and the memory leak is fixed. Till now the memory utilization is normal. In Laravel framework, its almost using this prepared statement. We can see so many laravel + prepare statements questions in StackOverflow.

SYS Schema in 5.7:

In MySQL 5.7 the sys schema provides all the informations about the MySQL’s memory Utilization.

# Credits: lefred.be
SELECT SUBSTRING_INDEX(event_name,'/',2) AS code_area, 
sys.format_bytes(SUM(current_alloc)) AS current_alloc
FROM sys.x$memory_global_by_current_bytes
GROUP BY SUBSTRING_INDEX(event_name,'/',2)
ORDER BY SUM(current_alloc) DESC;

Conclusion:

The very important lesson as a DBA I learned is, before setting up any parameter value check the consequences of modifying it and make sure it should not affect the production anymore. Now the mysql side is fine, but the application was throwing the below error.

Can't create more than max_prepared_stmt_count statements (current value: 20000)

To continue about this series, the next blog post will explain how we fixed the above error using multiplexing and how it helped to dramatically reduce the mysql’s memory utilization.