Memory leak with InnoDB temporary tables

[Raghavendra D Prabhu]

Reporting this bug based on the comments

https://bugs.launchpad.net/codership-mysql/+bug/1112514/comments/2

and bug http://bugs.mysql.com/bug.php?id=67259

Also, there were a few comments in https://bugs.launchpad.net/percona-server/+bug/1042946 which got lost (17 18 19 21 24 25)

So, this is to check for those.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Also, check if https://mariadb.atlassian.net/browse/MDEV-4016 is related to this.

[Raghavendra D Prabhu (raghavendra-prabhu)]

I slightly modified the sysbench benchmark to create InnoDB
temporary tables, with tmpdir being /tmp mounted with tmpfs.

Here is the massif output of the same: http://sprunge.us/begF

[Valerii Kravchuk (valerii-kravchuk)]

My test from http://bugs.mysql.com/bug.php?id=67259 shows similar RSS increase (that is not released after the test). Before (server started with --no-defaults):

openxs 2914 2.5 2.2 741952 89180 pts/0 Sl 09:41 0:00 /tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/bin/mysqld --no-defaults --basedir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64 --datadir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data --plugin-dir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/lib/plugin --log-error=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data/chief.err --pid-file=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data/chief.pid

After:

openxs 2914 7.2 5.1 1135168 208136 pts/0 Sl 09:41 0:08 /tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/bin/mysqld --no-defaults --basedir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64 --datadir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data --plugin-dir=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/lib/plugin --log-error=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data/chief.err --pid-file=/tmp/Percona-Server-5.6.10-alpha60.2-324.Linux.x86_64/data/chief.pid

[Jervin R (revin)]

Able to easily reproduce this on upstream 5.5.30 too:

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!

[Roel Van de Paar (roel11)]

Jervin, great work, please log as upstream bug and link this bug. Attach all Massif output to upstream bug as this validates the issue.

[Roel Van de Paar (roel11)]

Ah, see that has happened already. Please still add Massif output to upstream as it may be helpful there (stack etc.).

[Jervin R (revin)]

Re-attaching - 5.5.30

[Jervin R (revin)]

Reproduced on 5.5.31 too

[Valerii Kravchuk (valerii-kravchuk)]

Upstream bug seems fixed since 5.5.32. maybe it's time to check that fix and change status for this bug also?

[Laurynas Biveinis (laurynas-biveinis)]

Valerii -

Yes.

[Raghavendra D Prabhu (raghavendra-prabhu)]

x=1
while true;do
    mysql -e " CREATE TABLE source$x (id BIGINT, data BIGINT, PRIMARY KEY(id, data), INDEX (data)); INSERT INTO source$x (id, data) VALUES (1, 1), (2, 2), (3, 2), (4, 2), (5, 3); CREATE TEMPORARY TABLE temp$x (id BIGINT, data BIGINT, PRIMARY KEY (id, data)); INSERT INTO temp$x (id, data) SELECT id, data FROM source$x WHERE data = 2;";
    x=$(( x+1 ));
    sleep 1;
 done

still leaks memory. (I tested with small buffer pool and innodb-buffer-pool-populate)

[Valerii Kravchuk (valerii-kravchuk)]

What exact version(s) of Percona Server (or upstream MySQL server also) show the leak?

[Raghavendra D Prabhu (raghavendra-prabhu)]

I tested with latest HEAD at that time (should be 5.5.34 now) but
should be repeatable now I guess. But, the question is, whether
the memory increase seen there an actual leak or due to buffering
elsewhere.

[Nilnandan Joshi (nilnandan-joshi)]

Verified with Server version: 5.5.35-33.0 Percona Server (GPL), Release 33.0
Both VSZ and RSS both are incresing. Even dictionary memory.

Before TEST
-----------------------------------------------------------------------------------------------------

nilnandan@Dell-XPS:~$ ps aux | grep mysqld
root 9750 0.0 0.0 4444 764 pts/4 S 12:54 0:00 /bin/sh /usr/bin/mysqld_safe
mysql 10097 0.6 1.0 567984 84044 pts/4 Sl 12:54 0:00 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
1000 10251 0.0 0.0 13632 948 pts/5 S+ 12:55 0:00 grep --color=auto mysqld
nilnandan@Dell-XPS:~$

BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137756672; in additional pool allocated 0
Total memory allocated by read views 88
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2315888 (2213368 + 102520)
    Page hash 139112 (buffer pool 0 only)
    Dictionary cache 4562188 (554768 + 4007420)
    File system 83536 (82672 + 864)
    Lock system 333248 (332872 + 376)
    Recovery system 0 (0 + 0)
Dictionary memory allocated 4007420
Buffer pool size 8191
Buffer pool size, bytes 134201344
Free buffers 6435
Database pages 1750
Old database pages 665
Modified db pages 0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1750, created 0, written 0
51.81 reads/s, 0.00 creates/s, 0.00 writes/s
Buffer pool hit rate 973 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1750, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]

AFTER TEST (3 minutes run the script)
-----------------------------------------------------------------------------------------------------

nilnandan@Dell-XPS:~$ ps aux | grep mysqld
root 9750 0.0 0.0 4444 764 pts/4 S 12:54 0:00 /bin/sh /usr/bin/mysqld_safe
mysql 10097 0.6 1.1 699252 90824 pts/4 Sl 12:54 0:02 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.log --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
1000 10776 0.0 0.0 13632 948 pts/5 S+ 13:00 0:00 grep --color=auto mysqld
nilnandan@Dell-XPS:~$

----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 137756672; in additional pool allocated 0
Total memory allocated by read views 88
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 2315888 (2213368 + 102520)
    Page hash 139112 (buffer pool 0 only)
    Dictionary cache 5522992 (554768 + 4968224)
    File system 83536 (82672 + 864)
    Lock system 333248 (332872 + 376)
    Recovery system 0 (0 + 0)
Dictionary m...

[Laurynas Biveinis (laurynas-biveinis)]

Nil -

Could you repeat the test with Oracle MySQL 5.5 and log a new upstream bug as needed?

If possible, a Massif trace would be helpful too.

[Nilnandan Joshi (nilnandan-joshi)]

Apologies, it seems my test script was not realistic. Actually, I was creating tables and temporary tables without cleaning up and it caused to increase the memory consumption. After discussion with Jervin, I have tried to run below script on MySQL 5.5.35 and Percona server 5.5.35 where I have also dropped the table.

x=1
while true;do
    mysql -D test -e " CREATE TABLE source$x (id BIGINT, data BIGINT, PRIMARY KEY(id, data), INDEX (data)); INSERT INTO source$x (id, data) VALUES (1, 1), (2, 2), (3, 2), (4, 2), (5, 3); CREATE TEMPORARY TABLE temp$x (id BIGINT, data BIGINT, PRIMARY KEY (id, data)); INSERT INTO temp$x (id, data) SELECT id, data FROM source$x WHERE data = 2;DROP TABLE source$x;";
    x=$(( x+1 ));
    sleep 1;
 done

[root@percona1 ~]# ps aux | grep mysqld
mysql 2661 5.5 8.8 467284 136128 pts/0 Sl 12:41 0:01 valgrind --tool=massif --massif-out-file=/tmp/massif.out /usr/sbin/mysqld
root 2683 0.0 0.0 103240 848 pts/1 S+ 12:41 0:00 grep mysqld
[root@percona1 ~]#

Dictionary memory allocated 33650

######### After ran script for 8 to 10 minutes ###############

[root@percona1 ~]# ps aux | grep mysqld
mysql 2661 2.6 9.2 469004 142604 pts/0 Sl 12:41 0:07 valgrind --tool=massif --massif-out-file=/tmp/massif.out /usr/sbin/mysqld
root 3090 0.0 0.0 103240 844 pts/1 S+ 12:45 0:00 grep mysqld
[root@percona1 ~]#

Dictionary memory allocated 33650

There is no much difference in VSZ and RSS. Even Dictionary memory allocation is also same and not noticeable changes in massif output.

98.58% (33,053,658B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->42.17% (14,140,253B) 0x834221: ut_malloc_low (in /usr/sbin/mysqld)
| ->20.97% (7,032,192B) 0x8E20C4: os_event_create (in /usr/sbin/mysqld)
| | ->03.82% (1,280,000B) 0x80974E: srv_init (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x809CCB: srv_boot (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x81048B: innobase_start_or_create_for_mysql (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x7D075C: innobase_init(void*) (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x699126: ha_initialize_handlerton(st_plugin_int*) (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x59E608: plugin_initialize(st_plugin_int*) (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x5A2B5B: plugin_init(int*, char**, int) (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x51CDED: init_server_components() (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x52098B: mysqld_main(int, char**) (in /usr/sbin/mysqld)
| | | ->03.82% (1,280,000B) 0x6123D1B: (below main) (in /lib64/libc-2.12.so)

98.58% (33,121,791B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->42.09% (14,140,253B) 0x834221: ut_malloc_low (in /usr/sbin/mysqld)
| ->20.93% (7,032,192B) 0x8E20C4: os_event_create (in /usr/sbin/mysqld)
| | ->03.81% (1,280,000B) 0x80974E: srv_init (in /usr/sbin/mysqld)
| | | ->03.81% (1,280,000B) 0x809CCB: srv_boot (in /usr/sbin/mysqld)
| | | ->03.81% (1,280,000B) 0x81048B: innobase_start_or_create_for_mysql (in /usr/sbin/mysqld)
| | | ->03.81% (1,280...

[Nilnandan Joshi (nilnandan-joshi)]

Run above test on 5.6.15 but there too, no much difference in VSZ and RSS. Even Dictionary memory allocation is also same and not noticeable changes in massif output.

Before Test

root@Dell-XPS:~# ps aux | grep mysql
mysql 16055 11.2 2.5 599344 206804 pts/3 Sl 16:19 0:09 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/massif.out /usr/sbin/mysqld

Dictionary memory allocated 138338

After Test

root@Dell-XPS:~# ps aux | grep mysqld
mysql 16055 20.8 2.6 599344 214984 pts/3 Sl 16:19 1:10 /usr/bin/valgrind.bin --tool=massif --massif-out-file=/tmp/massif.out /usr/sbin/mysqld

Dictionary memory allocated 138338

99.83% (139,535,953B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->46.05% (64,355,920B) 0x907FA5: pfs_malloc(unsigned long, int) (in /usr/sbin/mysqld)
| ->11.33% (15,834,304B) 0x90DE93: init_table_share(unsigned int) (in /usr/sbin/mysqld)
| | ->11.33% (15,834,304B) 0x911792: initialize_performance_schema(PFS_global_param*) (in /usr/sbin/mysqld)
| | ->11.33% (15,834,304B) 0x5D0CFB: mysqld_main(int, char**) (in /usr/sbin/mysqld)
| | ->11.33% (15,834,304B) 0x6709EA3: (below main) (libc-start.c:260)

99.73% (121,100,513B) (heap allocation functions) malloc/new/new[], --alloc-fns, etc.
->53.00% (64,355,920B) 0x907FA5: pfs_malloc(unsigned long, int) (in /usr/sbin/mysqld)
| ->13.04% (15,834,304B) 0x90DE93: init_table_share(unsigned int) (in /usr/sbin/mysqld)
| | ->13.04% (15,834,304B) 0x911792: initialize_performance_schema(PFS_global_param*) (in /usr/sbin/mysqld)
| | ->13.04% (15,834,304B) 0x5D0CFB: mysqld_main(int, char**) (in /usr/sbin/mysqld)
| | ->13.04% (15,834,304B) 0x6709EA3: (below main) (libc-start.c:260)

[Shahriyar Rzayev (rzayev-sehriyar)]

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