MySQL Bugs: #67259: MySQL 5.5.x uses more memory than 5.1.x when temporary tables are used

Bug #67259	MySQL 5.5.x uses more memory than 5.1.x when temporary tables are used
Submitted:	16 Oct 2012 10:21	Modified:	8 Jul 2013 12:08
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: DML	Severity:	S2 (Serious)
Version:	5.5.27, 5.5.28	OS:	Linux ( 2.6.35.14-106.fc14.x86_64)
Assigned to:		CPU Architecture:	Any
Tags:	regression

Description:
I've noted many cases when after upgrade to 5.5.x MySQL starts to use notably more memory (with the same my.cnf) and eventually starts to use swap and runs out of memory. Reasons can be different (see https://bugs.launchpad.net/percona-server/+bug/1042946 for example), but recently I've identified a very suspicious use case, when implicit temporary tables are involved.

Using the same test case (see below) on a standalone server started with --no-defaults on 64-bit Linux, I get mysqld memory usage like:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
openxs    4229 18.4  3.3 457808 67612 pts/2    Sl   12:37   0:02 /home/openxs/dbs/5.5/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/5.5 --datadir=/home/openxs/dbs/5.5/data --plugin-dir=/home/openxs/dbs/5.5/lib/plugin --log-error=/home/openxs/dbs/5.5/data/chief.err --pid-file=/home/openxs/dbs/5.5/data/chief.pid

before the test and

openxs    4229  5.3  8.5 523604 173816 pts/2   Sl   12:37   0:42 /home/openxs/dbs/5.5/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/5.5 --datadir=/home/openxs/dbs/5.5/data --plugin-dir=/home/openxs/dbs/5.5/lib/plugin --log-error=/home/openxs/dbs/5.5/data/chief.err --pid-file=/home/openxs/dbs/5.5/data/chief.pid

after it. Same test on 5.1.65 started with --no-dafaults on the same system gives:

openxs    4548  2.0  1.3 272056 27888 pts/2    Sl   12:52   0:00 /home/openxs/dbs/5.1/libexec/mysqld --no-defaults --basedir=/home/openxs/dbs/5.1 --datadir=/home/openxs/dbs/5.1/var --log-error=/home/openxs/dbs/5.1/var/chief.err --pid-file=/home/openxs/dbs/5.1/var/chief.pid

before the test and

openxs    4548 11.8  1.8 403388 37812 pts/2    Sl   12:52   0:21 /home/openxs/dbs/5.1/libexec/mysqld --no-defaults --basedir=/home/openxs/dbs/5.1 --datadir=/home/openxs/dbs/5.1/var --log-error=/home/openxs/dbs/5.1/var/chief.err --pid-file=/home/openxs/dbs/5.1/var/chief.pid

after it. Compare RSS increase!

I think this is somewhat related to default storage engine being InnoDB in 5.5 (and probably it is used for internal temporary tables as well, see bug #49232), but still even after closing single session used (and thus freeing all temporary tables I'd assume) we see notably higher increase of RSS memory usege in 5.5 comparing to 5.1.

How to repeat:
1. Check memory usage with ps aux | grep mysqld
2. Execute the following SQL in single connected session:

create table ti2(c1 int auto_increment primary key, c2 char(255)) engine=InnoDB;
insert into ti2(c2) values('abc');
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;
insert into ti2(c2) select c2 from ti2;

3. Monitor RSS size for mysql when table gets big enough, then stop at this stage:

...
Query OK, 262144 rows affected (29.15 sec)
Records: 262144  Duplicates: 0  Warnings: 0

when temporary tables becomes big enough to be stored on disk:

mysql> show status like '%tmp%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 3     |
| Created_tmp_files       | 6     |
| Created_tmp_tables      | 21    |
+-------------------------+-------+
3 rows in set (0.00 sec)

Then exit from this session (you can try to do flush tables, drop table ti2 etc), check that memory usage at InnoDB level (according to INNODB STATUS) is changed only slightly, at dictionary pool:

Before:

Total memory allocated 138608640; in additional pool allocated 0
Dictionary memory allocated 70064

After:

Total memory allocated 138608640; in additional pool allocated 0
Dictionary memory allocated 74193

and check memory usage with ps aux | grep mysqld again, having zero sessions connected. Do this for 5.1.x and 5.5.x and make your won conclusions.

Suggested fix:
- Do not use InnoDB for internal temporary tables on 5.5, or

- Find memory leak (simple valgrind tests found nothing for me so far), or

- Explain why it is expected and normal to have higher memory usage with 5.5 in this case

A couple of comments regarding looking into MySQL memory leaks:

- RSS should only be used for guidance, it does not really show whether there is a leak. There is no guarantee that the memory is returned to the OS once memory is released by mysqld (for example, the malloc library might decide to cache it).

- Valgrind is not likely to catch pool leaks. A common memory leak occurrence is when MySQL allocates from a memory pool that is either permanent or has the wrong lifetime/scope. Given that memory pools are automatically deallocated when the mysqld process is exits, Valgrind won't be able to detect allocations from the pool as leaks.

- Google's heap profiler (bundled with tcmalloc) can be useful to manually check for leaks. Use it to compare the profiler output between runs (e.g. leak and no leak runs) and look for additional (or larger) allocations.

I'll try profile this today.  In addition to Davi's comments:
o) internal temp tables in 5.5 are really MyISAM.
o) will be using innodb plugin on 5.1.66
o) will be hardcoding the charset to utf8 and buffer pool size to 128M

Hi,

I have used a test case similar to Valeriy's and I do see MySQL consuming a lot of memory and not releasing it. I have run my tests against MySQL 5.5.15. 
My test executes queries that create implicit temporary tables with a big enough tmp_table_size that the implicit tmp tables are always created in memory.

First create a table and populate it with data as follows:

CREATE TABLE `ti2` (
  `c1` int(11) NOT NULL AUTO_INCREMENT,
  `c2` char(255) DEFAULT NULL,
  PRIMARY KEY (`c1`)
) ENGINE=InnoDB AUTO_INCREMENT=786406 DEFAULT CHARSET=latin1

mysql> insert into ti2(c2) values('abc');
Query OK, 1 row affected (0.08 sec)

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 1 row affected (0.08 sec)
Records: 1  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 2 rows affected (0.13 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 4 rows affected (0.10 sec)
Records: 4  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 8 rows affected (0.14 sec)
Records: 8  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 16 rows affected (0.11 sec)
Records: 16  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 32 rows affected (0.08 sec)
Records: 32  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 64 rows affected (0.11 sec)
Records: 64  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 128 rows affected (0.14 sec)
Records: 128  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 256 rows affected (0.09 sec)
Records: 256  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 512 rows affected (0.15 sec)
Records: 512  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 1024 rows affected (0.18 sec)
Records: 1024  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 2048 rows affected (0.19 sec)
Records: 2048  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 4096 rows affected (0.23 sec)
Records: 4096  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 8192 rows affected (0.39 sec)
Records: 8192  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 16384 rows affected (0.57 sec)
Records: 16384  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 32768 rows affected (1.21 sec)
Records: 32768  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 65536 rows affected (2.84 sec)
Records: 65536  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 131072 rows affected (5.60 sec)
Records: 131072  Duplicates: 0  Warnings: 0

mysql> insert into ti2(c2) select c2 from ti2;
Query OK, 262144 rows affected (10.95 sec)
Records: 262144  Duplicates: 0  Warnings: 0

The table size should be around 152M now:
mysql> show table status\G
*************************** 1. row ***************************
           Name: ti2
         Engine: InnoDB
        Version: 10
     Row_format: Compact
           Rows: 524349
 Avg_row_length: 305
    Data_length: 160088064
Max_data_length: 0
   Index_length: 0
      Data_free: 15728640
 Auto_increment: 786406
    Create_time: 2012-10-19 11:37:46
    Update_time: NULL
     Check_time: NULL
      Collation: latin1_swedish_ci
       Checksum: NULL
 Create_options: 
        Comment: 
1 row in set (0.00 sec)

Attached with this comment are 3 scripts:
memory_stats.sh
memory_usage_queries.sh
memory_usage_test.sh

Once the table ti2 has been created and populated with data as shown above, run the script as follows:
./memory_usage_test.sh $(pidof mysqld)

Note that this is a crude script, so it must be run from mysql-test dir.

The script above will increase allowed tmp table size to 256M, and will execute the following query in 16 concurrent sessions for 300 seconds:
select c2 from ti2 order by rand();

At the end of the test it will execute FLUSH TABLES. During the entire period the script will gather memory usage stats of mysqld and store it in a file memory_usage.log You can check this file to see memory usage through out the test.

During my run of the script, RSS of MySQL starts at ~49884K and ends up at 2154136K even after the queries have finished executing. Only after FLUSH TABLES is executed does RSS go down to 189004K. The memory is clearly not being released properly. Executing the above query with enough concurrency and for a longer period, we can see that MySQL would be using too much memory than it should.

I have also attached my.cnf file used, though its the one auto-generated by mtr.

Script to test memory usage from implicit temp tables

Attachment: mysql-test.tar.gz (application/x-gzip, text), 2.75 KiB.

The supplied test allows the queries to be executed in parallel. In such a case, it is likely that new table instances will be opened because there won't be any in the table cache. In this case, Open_tables will increase and FLUSH TABLES will free the memory that was allocated to create these new table instances.

Looking at the profiler output, the increase in memory is due to insert undo log segments that are cached for reuse. The initial increase in memory is that in this test it takes quite a while for them to get reused, but they eventually get reused and the memory usage will plateau.

Davi,

I do not agree with you that table cache is the reason why there is such a large increase in memory. Certainly it cannot explain why the memory usage increases from about 49M to about 2G.

Log of memory usage generated by my test script, but with tmp_table_size set to 10M

Attachment: memory_usage_10M_tmp_tbl_size.log (application/octet-stream, text), 2.69 KiB.

Davi,

Please see the file in my comment above. You can see that memory usage profile is very different when tmp_table_size is set to 10M. Note that in this case of tmp_table_size set to 10M, the implicit temporary table is not created in memory but rather created on-disk:

mysql> flush status;
Query OK, 0 rows affected (0.00 sec)

mysql> pager md5sum
PAGER set to 'md5sum'
mysql> select c2 from ti2 order by rand();
b65b12c37a028209966f1b728ef83e1c  -
524288 rows in set (1.38 sec)

mysql> nopager
PAGER set to stdout
mysql> show status like 'created%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 1     |
| Created_tmp_files       | 3     |
| Created_tmp_tables      | 1     |
+-------------------------+-------+
3 rows in set (0.00 sec)

So this shows that the problem is somewhere around in-memory temporary table and not because of table cache that was suggested.

Memory usage by implicit in-memory tmp tables on MySQL 5.5.23

Attachment: mysql_5523_mem_usage_256M_tmp_tbl_size.log (application/octet-stream, text), 4.62 KiB.

Memory usage by in-memory implicit tmp tables in MySQL 5.5.28

Attachment: mysql_5528_mem_usage_256M_tmp_tbl_size.log (application/octet-stream, text), 4.58 KiB.

Ok, I should have tested on latest release earlier. So after running my tests on MySQL 5.5.23 and MySQL 5.5.28, I can say that in the latest release I see that memory used by implicit in-memory temp tables is immediately freed.

> I do not agree with you that table cache is the reason why there is such a large increase in memory.

Note that I didn't say it was the reason, I was mainly pondering upon your comment about the change in memory usage triggered by FLUSH TABLES in the supplied test. Also, if I recall correctly, FLUSH TABLES has no connection what so ever with temporary tables, which would further note that it wasn't about temporary tables.

Davi,

The thing is that if you compare the memory usage (in the files I have attached) before and after FLUSH TABLES on 5.5.28 and 5.5.15, you can see that there is a clear difference. In my case, on 5.5.15 memory used by MySQL drops from 2.1G to 189M after FLUSH TABLES is executed. While on 5.5.28 memory is immediately released as the test queries finish executing and there isn't much memory released after the FLUSH TABLES call. So probably FLUSH TABLES did use to have something to do with implicit in-memory temp tables and their memory usage?

we are using MySQL 5.1.48 and can free more than 10G memory after running FLUSH TABLES on a memory-swapped machine.

It's confusing that "FLUSH TABLES" can free so much memory. 
Is there anyone can explain why?

Thank you for the report.

Verified as described with version 5.5.28. With 5.5.30, started from MTR, is not repeatable. Probably options matter.

Able to easily reproduce this on 5.5.30 and 5.5.31 too. Full massif outputs attached:

First snapshot:

->55.55% (72,727,165B) 0x7D2670: my_malloc (my_malloc.c:38)
| ->34.25% (44,844,632B) 0x7CCBDC: alloc_root (my_alloc.c:217)
| | ->33.88% (44,354,496B) 0x76759E: get_quick_keys(PARAM*, QUICK_RANGE_SELECT*, st_key_part*, SEL_ARG*, unsigned char*, unsigned int, unsigned char*, unsigned int) (sql_list.h:41)

Last snapshot:

->79.31% (289,033,461B) 0x7D2670: my_malloc (my_malloc.c:38)
| ->68.72% (250,442,320B) 0x7CCBDC: alloc_root (my_alloc.c:217)
| | ->68.59% (249,952,256B) 0x76759E: get_quick_keys(PARAM*, QUICK_RANGE_SELECT*, st_key_part*, SEL_ARG*, unsigned char*, unsigned int, unsigned char*, unsigned int) (sql_list.h:41)

my.cnf:

[mysqld]
bulk_insert_buffer_size = 32M
datadir = /var/lib/mysql
socket = /var/lib/mysql/mysql.sock
skip-name-resolve
transaction-isolation = READ-COMMITTED
join_buffer_size = 2M
long_query_time = 5
innodb_flush_log_at_trx_commit = 1
innodb_lock_wait_timeout = 60
log-bin-trust-function-creators
sync_binlog = 1
innodb_locks_unsafe_for_binlog = 1
innodb_file_per_table
innodb_data_file_path = ibdata1:32M:autoextend
innodb_buffer_pool_size = 128M
innodb_additional_mem_pool_size = 20M
innodb_log_buffer_size = 32M
innodb_log_file_size = 1024M
innodb_open_files = 16384
thread_cache = 128
table_cache = 512
max_heap_table_size = 128M
tmp_table_size = 128M
key_buffer_size = 24M
open_files_limit = 100000
query_cache_type = 0
query_cache_size = 0
max_connections = 200
read_buffer_size = 1M
max_allowed_packet = 400M
innodb_use_sys_malloc = 1

[mysql.server]
user = mysql

[safe_mysqld]
err-log = /var/log/mysqld.log
pid-file = /var/run/mysqld/mysqld.pid
tmp_table_size = 64M
max_allowed_packet = 400M

Full massif output is attached - thanks to Roel for validating!

Massif output from 5.5.30

Attachment: issue-30580-valgrind-massif-5.5.30.out (application/octet-stream, text), 555.72 KiB.

Massif output from 5.5.31

Attachment: issue-30580-valgrind-massif-5.5.31.out (application/octet-stream, text), 674.45 KiB.

Looks like this bug has been fixed on 5.5.32 via Bug #15978766 

http://dev.mysql.com/doc/relnotes/mysql/5.5/en/news-5-5-32.html

My same tests were not leaking memory anymore.

Valeriy,

we can not repeat this bug anymore: memory usage does not increase after test run. Please try with current version 5.5.32 in your environment and inform us if problem is still repeatable for you.

This is what I have with 5.5.32 built from sources in the same environment and for the same original test case:

Before the test:

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
...
openxs    4843  0.6  0.7 522640 61220 pts/0    Sl   09:36   0:00 /home/openxs/dbs/5.5/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/5.5 --datadir=/home/openxs/dbs/5.5/data --plugin-dir=/home/openxs/dbs/5.5/lib/plugin --log-error=/home/openxs/dbs/5.5/data/chief.err --pid-file=/home/openxs/dbs/5.5/data/chief.pid

After the test:

openxs    4843  3.8  2.0 522640 168416 pts/0   Sl   09:36   0:05 /home/openxs/dbs/5.5/bin/mysqld --no-defaults --basedir=/home/openxs/dbs/5.5 --datadir=/home/openxs/dbs/5.5/data --plugin-dir=/home/openxs/dbs/5.5/lib/plugin --log-error=/home/openxs/dbs/5.5/data/chief.err --pid-file=/home/openxs/dbs/5.5/data/chief.pid

I still see notable increase of RSS value.

Valeriy,

higher number of memory used in 5.5 can be because default value of InnoDB buffer pool is larger than in 5.1 Could you please repeat your test in 5.1 with option --innodb_buffer_pool_size=128M?

What we have in our internal tests:

In mysql-5.1:
BEFORE the query is run :-
xyz   17381  0.8  0.5 467140 44636 pts/1    Sl   15:13   0:00 mysqld
--defaults-file=my.cnf --innodb_buffer_pool_size=128M

AFTER the query is run :-
xyz   17381 16.0  2.1 532676 175328 pts/1   Sl   15:13   0:14 mysqld
--defaults-file=my.cnf --innodb_buffer_pool_size=128M

In mysql-5.5:
BEFORE the query is run :-
xyz    8846  1.3  0.5 581256 43744 pts/2    Sl   15:25   0:00 mysqld
--defaults-file=my.cnf

AFTER the query is run :-
xyz    8846 27.4  2.1 777864 173284 pts/2   Sl   15:25   0:32 mysqld
--defaults-file=my.cnf

So you can see that memory increase is same: 0.5 to 2.1.

This is what I see in 5.1 with innodb_buffer_pool_size=128M added:

openxs    2641  0.3  0.5 476708 45932 pts/0    Sl   10:15   0:00 /home/openxs/dbs/5.1/libexec/mysqld --no-defaults --basedir=/home/openxs/dbs/5.1 --datadir=/home/openxs/dbs/5.1/var --innodb_buffer_pool_size=128M --log-error=/home/openxs/dbs/5.1/var/chief.err --pid-file=/home/openxs/dbs/5.1/var/chief.pid

openxs    2641  9.2  2.1 542244 176568 pts/0   Sl   10:15   0:18 /home/openxs/dbs/5.1/libexec/mysqld --no-defaults --basedir=/home/openxs/dbs/5.1 --datadir=/home/openxs/dbs/5.1/var --innodb_buffer_pool_size=128M --log-error=/home/openxs/dbs/5.1/var/chief.err --pid-file=/home/openxs/dbs/5.1/var/chief.pid

So yes, it seems remaining increase of RSS is related to bigger InnoDB buffer pool being used during the test. Time to close this bug as fixed probably.

Thank you for the test!

Closed as "Can't repeat".