Query to INFORMATION_SCHEMA.TABLES and INFORMATION_SCHEMA.COLUMNS leads to huge memory usage

Bug #1380895 reported by Paul Namuag
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Unassigned
5.1
Won't Fix
Medium
Unassigned
5.5
Fix Released
Medium
Unassigned
5.6
Fix Released
Medium
Unassigned

Bug Description

This upstream bug is hitting PS 5.5.30-rel30.2-log also http://bugs.mysql.com/bug.php?id=72322

Description:
On an example MySQL instance with 28k empty InnoDB tables, a specific query to information_schema.tables and information_schema.columns leads to memory consumption over 38GB RSS.

How to repeat:
Create 28000 tables with create_tables.php script attached to the issue.
Then run following query and watch memory utilization:

SELECT concat('Select ''', a.TABLE_SCHEMA,',',a.TABLE_NAME,',', DATA_LENGTH, ',', INDEX_LENGTH, ',', DATA_FREE, ','', count(*),', ''','',

ifnull(max(ifnull(length(',b.COLUMN_NAME,'),0)),0),', ''','',' ' ifnull(avg(ifnull(length(', b.COLUMN_NAME,'),0)),0) From ', a.TABLE_SCHEMA,'.',a.TABLE_NAME,';')
FROM information_schema.tables a,
     information_schema.columns b
WHERE (a.TABLE_NAME=b.TABLE_NAME
       AND a.TABLE_SCHEMA=b.TABLE_SCHEMA)
  AND a.TABLE_SCHEMA NOT IN ('mysql',
                             'wdmon',
                             'information_schema',
                             'performance_schema')
  AND b.DATA_TYPE IN ('blob',
                      'longblob',
                      'longtext',
                      'mediumblob',
                      'mediumtext',
                      'text')
UNION
SELECT concat('Select ''', TABLE_SCHEMA,',',TABLE_NAME,',', DATA_LENGTH, ',', INDEX_LENGTH, ',', DATA_FREE, ','', count(*),', ''','', 0,', ''','',' ' 0 From ', TABLE_SCHEMA,'.',TABLE_NAME,';')
FROM information_schema.tables a
WHERE concat(TABLE_SCHEMA,TABLE_NAME) NOT IN
    (SELECT concat(TABLE_SCHEMA,TABLE_NAME)
     FROM information_schema.columns
     WHERE DATA_TYPE IN ('blob',
                         'longblob',
                         'longtext',
                         'mediumblob',
                         'mediumtext',
                         'text'))
  AND TABLE_SCHEMA NOT IN ('mysql',
                           'wdmon',
                           'information_schema',
                           'performance_schema')
ORDER BY 1;

In peak time of the run, just before the query finishes, mysqld RSS size gets to 38.5032 GB. Notable memory usage growth starts when query state changes from "Opening tables" to "checking permissions".

The same behaviour on 5.5.36, 5.6.17 and 5.7.4. MySQL settings used:
query-cache-type = 0
query-cache-size = 0
innodb_buffer_pool_size = 1G
innodb_log_file_size = 2G
innodb_log_buffer_size = 64M
innodb_flush_log_at_trx_commit = 0
innodb_file_per_table
innodb_open_files = 50000
innodb_flush_method = O_DIRECT

Tables present on this instance:
mysql >SELECT engine, count(*) tables, concat(round(sum(table_rows)/1000000,2),'M') rows, concat(round(sum(data_length)/(1024*1024*1024),2),'G') data, concat(round(sum(index_length)/(1024*1024*1024),2),'G') idx, concat(round(sum(data_length+index_length)/(1024*1024*1024),2),'G') total_size, round(sum(index_length)/sum(data_length),2) idxfrac FROM information_schema.TABLES GROUP BY engine ORDER BY sum(data_length+index_length);
+--------------------+--------+-------+-------+-------+------------+---------+
| engine | tables | rows | data | idx | total_size | idxfrac |
+--------------------+--------+-------+-------+-------+------------+---------+
| NULL | 59 | NULL | NULL | NULL | NULL | NULL |
| CSV | 2 | 0.00M | 0.00G | 0.00G | 0.00G | NULL |
| PERFORMANCE_SCHEMA | 75 | 2.17M | 0.00G | 0.00G | 0.00G | NULL |
| MEMORY | 50 | NULL | 0.00G | 0.00G | 0.00G | NULL |
| MyISAM | 31 | 0.00M | 0.00G | 0.00G | 0.00G | 0.16 |
| InnoDB | 28007 | 0.34M | 0.46G | 0.85G | 1.31G | 1.87 |
+--------------------+--------+-------+-------+-------+------------+---------+
6 rows in set (1 min 4.41 sec)

Valgrind massif output attached.
In 5.7's ps_helper output we can see:
mysql [localhost] {root} (performance_schema) > select * from ps_helper.memory_global_by_current_allocated limit 10;
+--------------------------------------------+---------------+---------------+-------------------+------------+------------+----------------+
| event_name | current_count | current_alloc | current_avg_alloc | high_count | high_alloc | high_avg_alloc |
+--------------------------------------------+---------------+---------------+-------------------+------------+------------+----------------+
| memory/sql/thd::main_mem_root | 6140 | 35.75 GiB | 5.96 MiB | 6449 | 35.80 GiB | 5.68 MiB |
| memory/performance_schema/internal_buffers | 60 | 497.00 MiB | 8.28 MiB | 60 | 497.00 MiB | 8.28 MiB |
| memory/sql/TABLE | 10063 | 21.58 MiB | 2.20 KiB | 10138 | 21.98 MiB | 2.22 KiB |
| memory/sql/TABLE_SHARE::mem_root | 8012 | 18.83 MiB | 2.41 KiB | 8339 | 19.55 MiB | 2.40 KiB |
| memory/mysys/KEY_CACHE | 3 | 8.00 MiB | 2.67 MiB | 3 | 8.00 MiB | 2.67 MiB |
| memory/mysys/lf_node | 21219 | 1.36 MiB | 67 bytes | 21219 | 1.36 MiB | 67 bytes |
| memory/mysys/lf_slist | 20375 | 636.72 KiB | 32 bytes | 20375 | 636.72 KiB | 32 bytes |
| memory/mysys/IO_CACHE | 6 | 448.05 KiB | 74.67 KiB | 17 | 736.15 KiB | 43.30 KiB |
| memory/sql/sp_head::main_mem_root | 40 | 422.67 KiB | 10.57 KiB | 40 | 422.67 KiB | 10.57 KiB |
| memory/mysys/array_buffer | 84 | 372.12 KiB | 4.43 KiB | 99 | 389.35 KiB | 3.93 KiB |
+--------------------------------------------+---------------+---------------+-------------------+------------+------------+----------------+
10 rows in set (0.00 sec)

On a machine with 32GB of RAM this query triggers OOMkiller, so had to test on bigger one.

Suggested fix:
Fix if this is a memory leak. Or explain why this happens otherwise.

Revision history for this message
Paul Namuag (paul-namuag) wrote :
Revision history for this message
Paul Namuag (paul-namuag) wrote :
Revision history for this message
Paul Namuag (paul-namuag) wrote :
tags: added: upstream
Revision history for this message
Nilnandan Joshi (nilnandan-joshi) wrote :
Download full text (3.6 KiB)

Able to confirm with PS 5.6.21. With 12K tables, RSS grows from around 800MB to 5.2 GB and then mysql crashed by OOMKiller before query finish.

mysql> SELECT concat('Select ''', a.TABLE_SCHEMA,',',a.TABLE_NAME,',', DATA_LENGTH, ',', INDEX_LENGTH, ',', DATA_FREE, ','', count(*),', ''','', ifnull(max(ifnull(length(',b.COLUMN_NAME,'),0)),0),', ''','',' ' ifnull(avg(ifnull(length(', b.COLUMN_NAME,'),0)),0) From ', a.TABLE_SCHEMA,'.',a.TABLE_NAME,';') FROM information_schema.tables a,information_schema.columns b WHERE (a.TABLE_NAME=b.TABLE_NAME AND a.TABLE_SCHEMA=b.TABLE_SCHEMA) AND a.TABLE_SCHEMA NOT IN ('mysql','wdmon','information_schema','performance_schema') AND b.DATA_TYPE IN ('blob','longblob','longtext','mediumblob','mediumtext','text') UNION SELECT concat('Select ''', TABLE_SCHEMA,',',TABLE_NAME,',', DATA_LENGTH, ',', INDEX_LENGTH, ',', DATA_FREE, ','', count(*),', ''','', 0,', ''','',' ' 0 From ', TABLE_SCHEMA,'.',TABLE_NAME,';') FROM information_schema.tables a WHERE concat(TABLE_SCHEMA,TABLE_NAME) NOT IN (SELECT concat(TABLE_SCHEMA,TABLE_NAME) FROM information_schema.columns WHERE DATA_TYPE IN ('blob','longblob','longtext','mediumblob','mediumtext','text')) AND TABLE_SCHEMA NOT IN ('mysql','wdmon','information_schema','performance_schema') ORDER BY 1;
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

mysql> SELECT engine, count(*) tables, concat(round(sum(table_rows)/1000000,2),'M') rows, concat(round(sum(data_length)/(1024*1024*1024),2),'G') data, concat(round(sum(index_length)/(1024*1024*1024),2),'G') idx, concat(round(sum(data_length+index_length)/(1024*1024*1024),2),'G') total_size, round(sum(index_length)/sum(data_length),2) idxfrac FROM information_schema.TABLES GROUP BY engine ORDER BY sum(data_length+index_length);
+--------------------+--------+-------+-------+-------+------------+---------+
| engine | tables | rows | data | idx | total_size | idxfrac |
+--------------------+--------+-------+-------+-------+------------+---------+
| MEMORY | 60 | NULL | 0.00G | 0.00G | 0.00G | NULL |
| PERFORMANCE_SCHEMA | 52 | 0.07M | 0.00G | 0.00G | 0.00G | NULL |
| CSV | 2 | 0.00M | 0.00G | 0.00G | 0.00G | NULL |
| MyISAM | 31 | 0.00M | 0.00G | 0.00G | 0.00G | 0.18 |
| InnoDB | 12345 | 9.33M | 0.65G | 0.71G | 1.36G | 1.09 |
+--------------------+--------+-------+-------+-------+------------+---------+
5 rows in set (10.38 sec)

mysql>

nilnandan@Dell-XPS:~$ ps -aux | grep mysql
root 16431 0.0 0.0 4444 756 pts/15 S 14:40 0:00 /bin/sh /usr/bin/mysqld_safe
mysql 16815 28.0 10.3 1559480 835540 pts/15 Sl 14:40 0:15 /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=50000 --pid-file=/v...

Read more...

Revision history for this message
Paul Namuag (paul-namuag) wrote :
Download full text (10.9 KiB)

Upon my test, what happens is that MySQL restarts itself due to OOM.

- created tables using create_tables.php
- run SELECT concat('Select ''', a.TABLE_SCHEMA,',',a.TABLE_NAME,',', DATA_LENGTH, ',', INDEX_LENGTH, ',', DATA_FREE, ','', count(*),', ''','', ..... query
- the monitor using top, vmstat and show processlist
- mysql has OOM score of -1000

# cat /proc/`pidof mysqld`/oom_score_adj
-1000

-

Upon start:
-------------------

top:

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 5307 mysql 20 0 13.6g 11g 7320 S 1.0 82.4 0:19.22 mysqld

vmstat -Sm 2:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 1 0 0 2007 24 383 0 0 1916 465 244 360 8 2 90 0 0
 0 0 0 2007 24 383 0 0 0 0 36 56 1 0 99 0 0
 0 0 0 2007 24 383 0 0 0 0 35 52 1 0 99 0 0
 0 0 0 2007 24 383 0 0 0 0 39 55 1 0 99 0 0
 0 0 0 2007 24 383 0 0 0 0 42 53 1 0 99 0 0
 0 0 0 2007 24 383 0 0 0 0 34 50 1 0 99 0 0

free -m:
             total used free shared buffers cached
Mem: 14782 12868 1914 0 23 365
-/+ buffers/cache: 12479 2303
Swap: 2015 0 2015

cat /proc/`pidof mysqld`/oom_score_adj
-1000

sysctl vm.swappiness
vm.swappiness = 1

after a while:

Top:

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 5307 mysql 20 0 13.9g 13g 6628 S 99.1 91.5 2:29.73 mysqld
 4535 root 20 0 223m 4968 2648 S 0.0 0.0 0:00.07 mysql

show processlist:

+----+------+-----------+--------------------+---------+------+--------------+---------+-----------+---------------+
| id | user | host | db | command | time | state | time_ms | rows_sent | rows_examined |
+----+------+-----------+--------------------+---------+------+--------------+---------+-----------+---------------+
| 1 | root | localhost | information_schema | Query | 151 | Sending data | 150846 | 0 | 0 |
+----+------+-----------+--------------------+---------+------+--------------+---------+-----------+---------------+

free -m:

             total used free shared buffers cached
Mem: 14782 14608 174 0 3 759
-/+ buffers/cache: 13845 937
Swap: 2015 0 2015

vmstat:

procs -----------memory---------- ---swap-- -----io---- --system-- -----...

Revision history for this message
Paul Namuag (paul-namuag) wrote :

See note #6

Revision history for this message
Paul Namuag (paul-namuag) wrote :
Download full text (9.0 KiB)

# mysqld --version
mysqld Ver 5.5.40-36.1-log for Linux on x86_64 (Percona Server (GPL), Release 36.1, Revision 707)

UPON START:
====================
top - 06:12:54 up 1 min, 1 user, load average: 0.00, 0.00, 0.00
Tasks: 92 total, 1 running, 91 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.0%us, 0.3%sy, 0.0%ni, 99.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 15137652k total, 528752k used, 14608900k free, 27688k buffers
Swap: 2064376k total, 0k used, 2064376k free, 61304k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 1612m 249m 5796 S 0.3 1.7 0:00.81 mysqld

free -m:

             total used free shared buffers cached
Mem: 14782 555 14227 0 27 63
-/+ buffers/cache: 464 14318
Swap: 2015 0 2015

vmstat -Sm 2:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 0 0 0 14914 28 66 0 0 467 10 101 177 1 2 97 0 0
 0 0 0 14914 28 66 0 0 0 0 50 64 0 0 100 0 0
 0 0 0 14914 28 66 0 0 0 18 44 51 0 0 100 0 0

AFTER A WHILE:
==================

top - 06:23:04 up 11 min, 7 users, load average: 1.02, 0.67, 0.28
Tasks: 126 total, 1 running, 125 sleeping, 0 stopped, 0 zombie
Cpu(s): 61.7%us, 38.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.3%hi, 0.0%si, 0.0%st
Mem: 15137652k total, 5942004k used, 9195648k free, 28636k buffers
Swap: 2064376k total, 0k used, 2064376k free, 2509120k cached

  PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
 1611 mysql 20 0 3468m 2.9g 7284 S 99.4 20.1 4:24.12 mysqld

show processlist:

+----+------+-----------+------+---------+------+----------------------+---------+
| id | user | host | db | command | time | state | time_ms |
+----+------+-----------+------+---------+------+----------------------+---------+
| 1 | root | localhost | NULL | Query | 289 | checking permissions | 288799 |
+----+------+-----------+------+---------+------+----------------------+---------+

free -m:

             total used free shared buffers cached
Mem: 14782 5372 9410 0 27 2450
-/+ buffers/cache: 2894 11888
Swap: 2015 0 2015

vmstat -Sm 2:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r b swpd free buff cache si so bi bo in cs us sy id wa st
 1 0 0 9455 29 2569 0 0 0 0 1000 79 61 39 0 0 0
 1 0 0 9414 29 2569 0 0 0 30 1012 87 62 39 0 0 0
 1 0 0 9373 29 2569 0 0 0 0 1005 70 60 40 0 0 0
 1 0 ...

Read more...

Revision history for this message
Paul Namuag (paul-namuag) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.