Memory leak when using per-query variables with subquery temp tables

[Ovais Tariq]

When per query variable feature is used to set max_statement_time Percona Server starts leaking memory for every statement.

-- Leak when using per-query-variable

USER PID RSS VSZ TIME COMMAND
mysql 53142 52383724 602199572 06:33:27 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=65536 --pid-file=/var/run/mysqld/

for (( i=0; i<10000; i++ )); do mysql -e "SET STATEMENT max_statement_time=1 FOR SELECT s.*, 'shard9' as shard_number FROM shard9.tbl s JOIN (SELECT binary_col, varchar_col, max(int_col) AS int_col FROM shard9.tbl t WHERE t.binary_col IN (SELECT DISTINCT binary_col FROM shard9.tbl) GROUP BY t.binary_col, t.varchar_col) AS r ON s.binary_col = r.binary_col AND s.varchar_col = r.varchar_col AND s.int_col = r.int_col;" > /dev/null 2>&1; done

USER PID RSS VSZ TIME COMMAND
mysql 53142 55718656 602199572 06:33:40 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=65536 --pid-file=/var/run/mysqld/

diff in memory = 3MB

-- No leak when setting the same variable as session variable

The same query executed by setting SESSION variable:

USER PID RSS VSZ TIME COMMAND
mysql 53142 55722752 602199572 06:33:40 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=65536 --pid-file=/var/run/mysqld/

for (( i=0; i<10000; i++ )); do mysql -e "SET SESSION max_statement_time=1; SELECT s.*, 'shard9' as shard_number FROM shard9.tbl s JOIN (SELECT binary_col, varchar_col, max(int_col) AS int_col FROM shard9.tbl t WHERE t.binary_col IN (SELECT DISTINCT binary_col FROM shard9.tbl) GROUP BY t.binary_col, t.varchar_col) AS r ON s.binary_col = r.binary_col AND s.varchar_col = r.varchar_col AND s.int_col = r.int_col;" > /dev/null 2>&1; done

USER PID RSS VSZ TIME COMMAND
mysql 53142 55728912 602199572 06:33:52 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=65536 --pid-file=/var/run/mysqld/

diff in memory = 6KB

Before both the tests, MySQL was restarted.

I ran the same tests with Valgrind and that shows the leak more evidently.

valgrind --tool=massif --massif-out-file=/tmp/valgrind/massif.out --depth=100 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --open-files-limit=65536 --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --innodb-numa-interleave=1 --innodb-buffer-pool-size=10G

-- Valgrind (leaky)
USER PID RSS VSZ TIME COMMAND
mysql 34021 1968452 12701116 00:00:05 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/valgrind/massif.out /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=

for (( i=0; i<10000; i++ )); do mysql -e "SET STATEMENT max_statement_time=1 FOR SELECT s.*, 'shard9' as shard_number FROM shard9.tbl s JOIN (SELECT binary_col, varchar_col, max(int_col) AS int_col FROM shard9.tbl t WHERE t.binary_col IN (SELECT DISTINCT binary_col FROM shard9.tbl) GROUP BY t.binary_col, t.varchar_col) AS r ON s.binary_col = r.binary_col AND s.varchar_col = r.varchar_col AND s.int_col = r.int_col;" > /dev/null 2>&1; done

USER PID RSS VSZ TIME COMMAND
mysql 111410 16707852 27532328 00:06:05 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/valgrind/massif.out --depth=100 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql

-- Valgrind (non-leaky)
USER PID RSS VSZ TIME COMMAND
mysql 78481 1970676 12701116 00:00:04 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/valgrind/massif.out /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=

for (( i=0; i<10000; i++ )); do mysql -e "SET SESSION max_statement_time=1; SELECT s.*, 'shard9' as shard_number FROM shard9.tbl s JOIN (SELECT binary_col, varchar_col, max(int_col) AS int_col FROM shard9.tbl t WHERE t.binary_col IN (SELECT DISTINCT binary_col FROM shard9.tbl) GROUP BY t.binary_col, t.varchar_col) AS r ON s.binary_col = r.binary_col AND s.varchar_col = r.varchar_col AND s.int_col = r.int_col;" > /dev/null 2>&1; done

USER PID RSS VSZ TIME COMMAND
mysql 78481 1998824 12733428 00:05:40 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/valgrind/massif.out /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=

[Ovais Tariq (ovais-tariq)]

You can see in the the massif output that memory is never released and the memory usage just keeps increasing to 16GB.

[Ovais Tariq (ovais-tariq)]

ms_print output from report_leak.out

[Ovais Tariq (ovais-tariq)]

Massif output when running the same test but without using per-query-variable. As you can see the memory usage is stable through out.

[Laurynas Biveinis (laurynas-biveinis)]

What is your server version? Are you using the audit log plugin? (massif suggests something else, but we recently fixed a SET STATEMENT memory leak which was related to the audit log plugin)

[Ovais Tariq (ovais-tariq)]

I have tested with 5.6.32 and 5.6.33. We don't use audit log plugin.

[Ovais Tariq (ovais-tariq)]

It also looks like MariaDB fixed a lot of bugs before porting this feature to MariaDB: https://jira.mariadb.org/browse/MDEV-5231
It may be interesting to test if leak is present in MariaDB.

[Miguel Angel Nieto (miguelangelnieto)]

Verified as described.

[Roel Van de Paar (roel11)]

Also see bug 1635789

[Laurynas Biveinis (laurynas-biveinis)]

Miguel, Roel -

What schema have you used in your reproduction attempts?

[Nickolay Ihalainen (ihanick)]

Default options for mysql-test-run & mysql 5.6,
Table type could be myisam or innodb.

500MB RSS and 1GB VSZ increase for each 10k queries.
A simple change (e.g. remove subquery) makes memory stable.

CREATE TABLE test.data (
row_key int NOT NULL DEFAULT 0,
ref_key bigint(20) NOT NULL
) ENGINE=MyISAM DEFAULT CHARSET=latin1;
INSERT INTO test.data (ref_key) VALUES (1),(2),(3),(4),(5),(6),(7),(8),(9),(10);
set @row_id := 0;
INSERT INTO test.data (ref_key) SELECT @row_id := @row_id + 11 as ref_key FROM test.data t1, test.data t2, test.data t3, test.data t4, test.data t5;

QUERY=" SELECT count(1) FROM test.data s JOIN (SELECT row_key, ref_key AS ref_key FROM test.data t WHERE t.row_key IN (SELECT row_key FROM test.data) ) AS r;"

ps -o rss,vsz,cmd -p `pgrep -xn mysqld` | cat
(for i in `seq 10000` ; do $MYSQL_CLI -e "SET STATEMENT max_statement_time=1 FOR $QUERY" 2>&1 > /dev/null ; done) 2>&1 > /dev/null

[Laurynas Biveinis (laurynas-biveinis)]

A workaround is to set session, not statement max_statement_time:

SET max_statement_time=...
SELECT ...
SET max_statement_time=DEFAULT

The bug itself indeed has been fixed in MariaDB in their feature rewrite.

[Laurynas Biveinis (laurynas-biveinis)]

The root cause is shared with bug 1392375

[Ovais Tariq (ovais-tariq)]

@laurynas, yup I have mentioned the workaround in the bug report. Setting the session variable normally does not introduce the memory leak.

[Laurynas Biveinis (laurynas-biveinis)]

    https://github.com/percona/percona-server/pull/1273
    https://github.com/percona/percona-server/pull/1274

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1025