Page MenuHomePhabricator

Investigate possible memory leak on db1115
Open, NormalPublic

Description

Tendril seems to be having an excessive amount of memory consumption that keeps growing over the time until it makes OOM to kick in and start killing some processes, typically MySQL or nagios, causing pages

Examples of some tasks:
T231165: db1115 (tendril) paged twice in 24h due to OOM
T196726: db1115 (tendril DB) had OOM for some processes and some hw (memory) issues

Some graphs that show this behavior:


Tendril heavily uses the event scheduler with lots of events:

# mysql.py -hdb1115 tendril -e "show events" | wc -l
2267

MySQL is configured to use 20GB of pool_size.

innodb_buffer_pool_size        = 20G

As of now (1st Sept 05:32 AM UTC) this is the memory consumption:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
29136 mysql     20   0  0.106t 0.062t  25624 S 244.4 50.3  41014:10 mysqld
root@db1115:/home/marostegui# free -g
              total        used        free      shared  buff/cache   available
Mem:            125          63           0           1          61          59
Swap:             0           0           0
# pmap 29136 | grep total
 total        113386168K
mysql:root@localhost [(none)]> show global status like 'Uptime';
+---------------+--------+
| Variable_name | Value  |
+---------------+--------+
| Uptime        | 657836 |
+---------------+--------+
1 row in set (0.00 sec)

There are some (some of them quite old) bugs claiming to have some memory issues with events so maybe this could be similar:
https://bugs.mysql.com/bug.php?id=18683
https://forums.mysql.com/read.php?35,675519,675519
https://jira.mariadb.org/browse/MDEV-14260?attachmentViewMode=list

And this is the graph after the last crash T231165: db1115 (tendril) paged twice in 24h due to OOM

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptMon, Sep 2, 5:45 AM
Marostegui triaged this task as Normal priority.Mon, Sep 2, 5:46 AM
Marostegui moved this task from Triage to Meta/Epic on the DBA board.
Marostegui updated the task description. (Show Details)Mon, Sep 2, 5:56 AM

For now, I have left a cronjob on db1115 gathering a top output every 8h, so we can see how much the memory grows specifically for the MySQL process.
I am also planning to restart MySQL tomorrow without the event_scheduler for a few minutes, and later enable it to see how much it grows.

Mentioned in SAL (#wikimedia-operations) [2019-09-04T10:11:01Z] <marostegui> Stop MySQL on db1115 - T231769

Mentioned in SAL (#wikimedia-operations) [2019-09-04T10:11:35Z] <marostegui> Tendril/dbtree will be unavailable for a few minutes T231769

Mentioned in SAL (#wikimedia-operations) [2019-09-04T10:12:40Z] <marostegui> Stop MySQL on db1115 without the event scheduler - T231769

Mentioned in SAL (#wikimedia-operations) [2019-09-04T10:20:37Z] <marostegui> Start MySQL on db1115 without the event scheduler - T231769

Mentioned in SAL (#wikimedia-operations) [2019-09-04T10:41:52Z] <marostegui> Start event scheduler on db1115 T231769

These were the figures before I stopped mysql over the last 2 (I gather data every 8 hours, so 3 times a day) days - we can see MySQL memory growing every day:

29136 mysql     20   0  0.107t 0.063t  25624 S  1359 51.1  45283:05 mysqld
29136 mysql     20   0  0.107t 0.062t  25624 S 672.2 50.1  47047:23 mysqld
29136 mysql     20   0  0.107t 0.062t  25624 S 258.8 50.5  48856:46 mysqld
29136 mysql     20   0  0.108t 0.064t  25624 S 227.8 51.9  50679:09 mysqld
29136 mysql     20   0  0.108t 0.064t  25624 S 658.8 51.8  52411:51 mysqld
29136 mysql     20   0  0.108t 0.064t  25624 S 133.3 51.9  52818:32 mysqld

I have restarted mysql on db1115 without the event scheduler enabled.
Waited until the buffer pool was fully loaded and this is the memory consumption at the time

Sep 04 10:20:31 db1115 mysqld[1630]: 2019-09-04 10:20:31 7f1f36ff7700 InnoDB: Buffer pool(s) load completed at 190904 10:20:31

After that the memory values for the mysqld process kept growing from 17.5% (10:20:31) to 19.9% (10:40:06) when I started the event scheduler.

At that point the memory usage jumped from 19.9% to 21.3% (jumped almost 10G of VIRT) in a second (and still growing)
Visible on the graph as well:

Current status:

1630 mysql     20   0 49.415g 0.027t  24936 S 476.5 22.0  13:53.11 mysqld

I would like to leave the event_scheduler stopped for longer in a future test to see when the memory usage stops.

12:27:04

1630 mysql     20   0 67.313g 0.046t  24936 S 366.7 37.8 394:46.56 mysqld

So almost 20GB more in less than 2 hours after enabling event_scheduler

This is kinda the same behaviour we have: https://bugs.mysql.com/bug.php?id=95787

I just realised we do have enabled TokuDB there, with a pretty big buffer configured 30GB.
We don't have many TokuDB tables (as most of them are FEDERATED):

+-----------------------+--------+---------------------+
| table_name            | engine | update_time         |
+-----------------------+--------+---------------------+
| client_statistics_log | TokuDB | 2019-09-05 13:31:46 |
| general_log_sampled   | TokuDB | 2019-09-05 00:00:21 |
| global_status_log     | TokuDB | 2019-09-05 13:35:46 |
| global_status_log_5m  | TokuDB | 2019-09-05 13:35:50 |
| index_statistics_log  | TokuDB | 2019-09-05 13:34:47 |
| innodb_locks_log      | TokuDB | 2019-09-05 13:35:45 |
| innodb_trx_log        | TokuDB | 2019-09-05 13:35:45 |
| queries               | TokuDB | 2018-02-22 08:36:23 |
| queries_seen_log      | TokuDB | 2019-09-05 00:00:24 |
| query_footprint_log   | TokuDB | 2014-05-30 02:44:55 |
| slave_status_log      | TokuDB | 2019-09-05 13:36:40 |
| slow_log_sampled      | TokuDB | 2019-09-05 00:00:46 |
| table_statistics_log  | TokuDB | 2019-09-05 13:34:44 |
| user_statistics_log   | TokuDB | 2019-09-05 13:34:44 |
+-----------------------+--------+---------------------+
14 rows in set, 1 warning (4 min 56.98 sec)

@jcrespo do you have any idea if those tables are toku for any specific reason? (apart from compression?)

Those are the main tables where the historic metrics are stored- they are actually quite large. Most should disappear, but we cannot just convert them as they compress quite efficiently well compared to InnoDB compressed.

It has grown 50GB in 2 days. Right now we are at 90GB, and it increases around 2GB every 8 hours.
TokuDB buffer + Innodb buffer are 50GB, nowhere near those 90GB (and still increasing).

On Monday I am going to stop the event_scheduler again (without restarting mysql) for a few hours to check how the memory behaves and if it stops growing.