Percona Server moved to https://jira.percona.com/projects/PS

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

Series 5.5
Bug #1380895

Bug #1380895 reported by Paul Namuag on 2014-10-14

This bug affects 1 person

	Status	Importance	Assigned to	Milestone
MySQL Server	Unknown	Unknown	mysql-bugs #72322
Percona Server moved to https://jira.percona.com/projects/PS	Fix Released	Medium	Unassigned	Percona Server moved to https://jira.percona.com/projects/PS 5.6.25-73.0
5.1	Won't Fix	Medium	Unassigned
5.5	Fix Released	Medium	Unassigned	Percona Server moved to https://jira.percona.com/projects/PS 5.5.44-37.3
5.6	Fix Released	Medium	Unassigned	Percona Server moved to https://jira.percona.com/projects/PS 5.6.25-73.0

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.

Tags:

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-14:

create_tables.php Edit (937 bytes, application/x-httpd-php)

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-14:

I_S_mem_leak_massif_visual.png Edit (330.5 KiB, image/png)

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-14:

massif_5.7.4.out Edit (376.2 KiB, text/plain)

Valerii Kravchuk (valerii-kravchuk) on 2014-10-14

tags:

added: upstream

Revision history for this message

Nilnandan Joshi (nilnandan-joshi) wrote on 2014-10-15:

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...

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=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

nilnandan@Dell-XPS:~$ ps -aux | grep mysql
root     16431  0.0  0.0   4444   156 pts/15   S    14:40   0:00 /bin/sh /usr/bin/mysqld_safe
mysql    16815 70.6 65.2 6147000 5268200 pts/15 Sl  14:40   3:26 /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=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-15:

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

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-- -----...

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-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0      0    183      3    795    0    0     0    18 1011   90 99  1  0  0  0
 1  0      0    183      3    795    0    0     0     0 1007   86 99  1  0  0  0
 1  0      0    183      3    795    0    0     0     0 1008   80 99  1  0  0  0

show processlist:

+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+
| id | user | host      | db                 | command | time | state                | time_ms | rows_sent | rows_examined |
+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+
|  1 | root | localhost | information_schema | Query   |  238 | checking permissions |  238161 |         0 |         31091 |
+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+

free -m:

total       used       free     shared    buffers     cached
Mem:         14782      14651        131          0          2         86
-/+ buffers/cache:      14563        219
Swap:         2015         11       2004

show processlist:

+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+
| id | user | host      | db                 | command | time | state                | time_ms | rows_sent | rows_examined |
+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+
|  1 | root | localhost | information_schema | Query   |  240 | checking permissions |  240182 |         0 |         31175 |
+----+------+-----------+--------------------+---------+------+----------------------+---------+-----------+---------------+

free -m:

total       used       free     shared    buffers     cached
Mem:         14782      14650        132          0          2         74
-/+ buffers/cache:      14573        209
Swap:         2015         38       1977

top:

top - 15:51:14 up  1:24,  6 users,  load average: 1.67, 0.94, 0.43
Tasks: 110 total,   1 running, 109 sleeping,   0 stopped,   0 zombie
Cpu(s): 56.3%us, 43.3%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.0%hi,  0.3%si,  0.0%st
Mem:  15137652k total, 14990800k used,   146852k free,     2468k buffers
Swap:  2064376k total,  1463060k used,   601316k free,    13184k cached

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                    
 5307 mysql     20   0 16.2g  14g 2748 S 99.3 97.2   5:21.94 mysqld

vmstat -Sm 2:

1  1      0    173      2    337    0    0   610    30 1035  179 57 43  0  0  0
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  1      0    173      2    299    0    0   174     0 1019  162 59 41  0  0  0
 1  1      0    173      2    261    0    0   168    20 1027  159 62 39  0  0  0
 1  1      0    173      2    223    0    0   178     0 1020  153 59 41  0  0  0
 1  1      0    173      2    186    0    0   168     0 1024  155 59 41  0  1  0
 1  1      0    172      2    148    0    0   420    22 1029  178 60 40  0  0  0
 1  1      0    171      2    113    0    0   174     0 1018  156 59 41  0  0  0
 1  1      0    141      2    104    0    0   294    18 1021  160 55 45  0  0  0
 1  1     18    138      2     86    0    9   168  8976 1052  184 55 45  0  0  0
 1  1     48    138      2     75    0   15   200 14426 1065  189 56 44  0  0  0
 1  1     74    138      2     65    0   13   168 13164 1069  191 56 44  0  0  0
 1  1    103    141      2     56    0   14   164 14110 1064  187 54 46  0  0  0
 1  1    134    145      2     48    0   15   162 14972 1064  185 56 44  0  0  0
 1  1    163    143      2     41    0   15   310 14398 1075  189 55 44  0  1  0
 1  1    197    146      2     34    0   17   400 16202 1085  200 57 44  0  0  0
 1  1    229    148      2     29    0   16   162 15792 1069  185 57 43  0  0  0
 1  1    261    155      2     19    0   16   190 15892 1073  190 54 46  0  0  0
 1  1    297    160      3     14    0   18  2398 17148 1143  309 52 48  0  0  0
 1  1    336    161      2     12    0   20  1494 19226 1110  241 59 41  0  1  0
 1  1    368    163      2     10    0   16  1984 15708 1105  261 57 44  0  0  0
 1  0    392    149      2     11    0   12   516 11752 1071  178 57 43  0  0  0
 1  0    457    173      3     15    0   33  5282 31884 1226  382 55 45  0  1  0
 1  0    481    158      3     16    0   12   832 11584 1063  180 56 44  0  0  0
 3  1    503    148      2     14    0   11   762 10898 1069  183 57 44  0  0  0
 1  1    539    153      2     10    0   18   232 17324 1068  170 57 43  0  0  0
 1  0    588    165      2      8    0   24   400 23826 1097  201 59 41  0  1  0
 1  1    613    156      2      7    0   13   916 12550 1077  197 58 42  0  0  0

free -m:

free -m:
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 0  1   1973    166      2      9    0    0   962    18  346  140 16 13  0 72  0
 1  1   1989    156      2      6    0    8   140  7704  895  163 48 37  0 16  0
 1  0   2034    157      3     13    0   23  4846 22226 1160  361 53 47  0  1  0
 1  1   2063    151      2     10    0   14   272 14088 1057  187 57 43  0  0  0
 1  1   2098    157      2      5    0   17  1182 16808 1102  259 56 45  0  0  0
 1  1   2113    146      3     14    0    8  7864  7728 1203  449 53 47  0  0  0
 5  4   2113    132      0      2    0    0 49008    40 2293 2979 49 43  0  8  0

After this, the server triggers the OOM killer.

Oct 15 15:12:42 localhost kernel: mysqld invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=-17, oom_score_adj=-1000
...
Oct 15 15:12:42 localhost kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
Oct 15 15:12:42 localhost kernel: [ 2341]     0  2341    27063        1   0       0             0 mysqld_safe
Oct 15 15:12:42 localhost kernel: [ 2760]   498  2760  4407264  3680571   0     -17         -1000 mysqld

# mysqld --version
mysqld  Ver 5.6.19-67.0 for Linux on x86_64 (Percona Server (GPL), Release 67.0, Revision 618)

Will post versions for 5.1 and 5.5

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-15:

See note #6

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-16:

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

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

# 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      0   9332     29   2569    0    0     0     0 1008   73 61 39  0  0  0
 1  0      0   9291     29   2569    0    0     0    24 1010   95 63 37  0  0  0
 1  0      0   9250     29   2569    0    0     0     0 1009   71 61 40  0  0  0

top:

top - 06:34:09 up 22 min,  7 users,  load average: 1.17, 1.03, 0.66
Tasks: 126 total,   1 running, 125 sleeping,   0 stopped,   0 zombie
Cpu(s): 58.2%us, 40.1%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.7%hi,  1.0%si,  0.0%st
Mem:  15137652k total, 14978772k used,   158880k free,     2744k buffers
Swap:  2064376k total,  1566652k used,   497724k free,    11140k cached

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                    
 1611 mysql     20   0 16.5g  14g 2408 S 95.5 97.1  15:20.07 mysqld

show processlist:

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

free -m:

total       used       free     shared    buffers     cached
Mem:         14782      14645        137          0          2         12
-/+ buffers/cache:      14629        152
Swap:         2015       1654        361

vmstat:
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0   1011    149      2     13    0   20   376 19504 1085  173 54 46  0  0  0
 1  0   1051    152      2     14    0   20   232 19574 1083  161 55 45  0  1  0
...
 2  0   1859    155      2     15    0    0   552    30 1031  124 57 43  0  0  0
 1  2   1913    143      2     14    0   27   476 26462  927  170 48 37  0 14  0
 2  2   1914    145      3     12    0    1  7444   668  704 1176  3  8  0 89  0

This is the last part where OOM is triggered:
======================================

top (before OOM is triggered):
top - 06:34:55 up 23 min,  7 users,  load average: 1.89, 1.23, 0.74
Tasks: 116 total,   1 running, 115 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.3%us, 69.7%sy,  0.0%ni,  0.0%id,  0.0%wa,  0.7%hi, 29.3%si,  0.0%st
Mem:  15137652k total, 15008428k used,   129224k free,      120k buffers
Swap:  2064376k total,  2064376k used,        0k free,     2372k cached

PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                                                    
 1611 mysql     20   0 17.1g  14g   60 S 84.9 97.5  15:58.04 mysqld

processlist (before OOM is triggered):

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

free -m (before OOM is triggered):

total       used       free     shared    buffers     cached
Mem:         14782      14653        129          0          2         10
-/+ buffers/cache:      14641        141
Swap:         2015       2015          0

vmstat (before OOM is triggered):

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0   1011    149      2     13    0   20   376 19504 1085  173 54 46  0  0  0
 1  0   1051    152      2     14    0   20   232 19574 1083  161 55 45  0  1  0
 1  1   1085    150      2     13    0   17   372 16742 1072  183 59 42  0  0  0
 1  1   1124    151      2     10    0   20  1104 19236 1108  244 54 46  0  0  0
...
 2  0   1479    160      2     11    0   26   742 25366 1115  203 57 43  0  0  0
 1  1   1505    150      2     11    0   13  1120 12830 1091  228 60 40  0  0  0
 1  0   1546    150      2     12    0   20   356 19798 1083  176 57 43  0  0  0
 1  1   1582    149      2     11    0   18   582 17718 1086  197 58 42  0  0  0
...
 1  0   2098    173      2      9    0   26   532 25674 1107  226 53 47  0  0  0
 2  1   2110    150      2      8    0    6   914  6262 1067  187 57 43  0  0  0
 1  1   2113    137      2      8    0    2  1688  1470 1062  236 59 41  0  0  0
...
 3  2   2113    132      0      2    0    0 49628   524 3480 3773  0 100  0  0  0
 2  1   2113    132      0      1    0    0 171710   290 5093 6770  1 99  0  1  0
 3  4   2113    132      0      1    0    0 204980   102 4558 5691  0 100  0  0  0
 1 10   2113    139      0      3    1    2 171168  2180 5193 7528  1 95  0  4  0

iostat (before OOM is triggered):

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda             713.04   797.83 4342.39  158.70 289386.96  7691.30    66.00    17.65    3.96   0.21  95.71
dm-0              0.00     0.00 4071.20   30.98 253908.70   247.83    61.96    10.74    2.63   0.20  81.52
dm-1              0.00     0.00  369.57  886.41  2956.52  7091.30     8.00    28.59   22.90   0.46  57.99

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
sda             870.76  2369.59 3588.89  247.95 159054.97 21113.45    46.96    16.69    4.30   0.23  87.08
dm-0              0.00     0.00 3826.90   38.60 153974.27   308.77    39.91     5.00    1.29   0.21  81.35
dm-1              0.00     0.00  635.09 2600.58  5080.70 20804.68     8.00   214.77   66.38   0.22  72.28

dm-0 is the device where mysql data resides
dm-1 is the swap space

When state is "checking permissions" disk i/o is very low except when swap space is used as seen above. If sending data/opening tables, it’s high.

Revision history for this message

Paul Namuag (paul-namuag) wrote on 2014-10-16:

For comment #6 (looks gone), see https://bugs.launchpad.net/percona-server/+bug/1380895/comments/6