[MDEV-17996] ANALYZE TABLE x PERSISTENT FOR ALL - memory usage excessive / fails to complete Created: 2018-12-13  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Optimizer
Affects Version/s: 10.1.31, 10.3.10, 10.4.1
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Sergei Petrunia
Resolution: Unresolved Votes: 0
Labels: eits, leak
Environment:

fc29 x86_64 + debian x86_64 jessie container


 Description   

Starting mariadb from start and ran mysqldump to fully populate the innodb_buffer_pool. No other concurrenct activity on this database:

MariaDB [test]> shutdown;
 
Query OK, 0 rows affected (0.000 sec)
 
 
 
MariaDB [test]> Bye
 
 
 
$ sudo systemctl start mariadb.service
 
 
 
$  mysqldump -u root test > /dev/null
 
 
 
$  ps -uax  -q 28797
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 53.2  0.9 1381316 320828 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
[dan@volution systemd]$ mysql -u root -A test
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 9
 
Server version: 10.3.10-MariaDB MariaDB Server
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [test]> show global status like 'innodb_buffer_pool_pages%';
 
+----------------------------------+-------+
 
| Variable_name                    | Value |
 
+----------------------------------+-------+
 
| Innodb_buffer_pool_pages_data    | 7899  |
 
| Innodb_buffer_pool_pages_dirty   | 0     |
 
| Innodb_buffer_pool_pages_flushed | 131   |
 
| Innodb_buffer_pool_pages_free    | 0     |
 
| Innodb_buffer_pool_pages_misc    | 293   |
 
| Innodb_buffer_pool_pages_total   | 8192  |
 
+----------------------------------+-------+
 
6 rows in set (0.002 sec)
 
 
 
MariaDB [test]> 
MariaDB [test]> ANALYZE TABLE cost PERSISTENT FOR ALL;
 
+-----------+---------+----------+-----------------------------------------+
 
| Table     | Op      | Msg_type | Msg_text                                |
 
+-----------+---------+----------+-----------------------------------------+
 
| test.cost | analyze | status   | Engine-independent statistics collected |
 
| test.cost | analyze | status   | OK                                      |
 
+-----------+---------+----------+-----------------------------------------+
 
2 rows in set (35.188 sec)

Before the previous `ANALYZE TABLE` table was run the below script was run to monitor memory usage.

$ while [ 1 ];  do  ps -uax  -q 28797 ; sleep 1; done
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.6  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.4  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.2  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.0  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.9  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.7  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.5  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.3  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.1  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.9  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.8  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.6  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.4  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.2  0.9 1381316 321180 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.2  1.0 1421252 342032 ?      Ssl  14:15   1:39 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.5  1.0 1435588 353672 ?      Ssl  14:15   1:40 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.7  1.0 1447876 358688 ?      Ssl  14:15   1:41 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 41.9  1.1 1447876 359744 ?      Ssl  14:15   1:42 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.2  1.1 1447876 363968 ?      Ssl  14:15   1:43 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.4  1.1 1447876 363968 ?      Ssl  14:15   1:44 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.7  1.1 1447876 366080 ?      Ssl  14:15   1:45 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 42.9  1.1 1447876 366080 ?      Ssl  14:15   1:46 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.1  1.1 1447876 366080 ?      Ssl  14:15   1:47 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.4  1.1 1447876 366080 ?      Ssl  14:15   1:49 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.6  1.1 1447876 366080 ?      Ssl  14:15   1:50 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 43.8  1.1 1447876 366080 ?      Ssl  14:15   1:51 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 44.1  1.0 1447876 357888 ?      Ssl  14:15   1:52 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 44.3  1.0 1447876 357888 ?      Ssl  14:15   1:53 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 44.5  1.1 1447876 362636 ?      Ssl  14:15   1:54 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 44.8  1.1 1447876 362900 ?      Ssl  14:15   1:55 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 45.0  1.1 1447876 362900 ?      Ssl  14:15   1:56 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 45.2  1.1 1447876 363956 ?      Ssl  14:15   1:57 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 45.4  1.1 1447876 363956 ?      Ssl  14:15   1:58 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 45.6  1.0 1447876 348716 ?      Ssl  14:15   1:59 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 45.8  1.1 1447876 360856 ?      Ssl  14:15   2:00 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 46.0  1.1 1447876 361912 ?      Ssl  14:15   2:01 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 46.2  1.1 1447876 361912 ?      Ssl  14:15   2:02 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    28762 46.4  1.1 1472452 378280 ?      Ssl  14:15   2:03 /usr/libexec/mysqld --basedir=/usr

memory usage raised from 321M to 378M (57M)

MariaDB [test]> show create table cost;
 
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                                        |
 
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| cost  | CREATE TABLE `cost` (
 
  `id` varchar(40) NOT NULL,
 
  `snapshotActive` int(11) DEFAULT NULL,
 
  `billingAccountName` varchar(255) DEFAULT NULL,
 
  `period` int(11) NOT NULL,
 
  `cost` decimal(40,25) DEFAULT 0.0000000000000000000000000,
 
  PRIMARY KEY (`id`),
 
  KEY `periodActiveBillingCost` (`period`,`snapshotActive`,`billingAccountName`,`cost`),
 
  KEY `periodBillingCostActive` (`period`,`billingAccountName`,`cost`,`snapshotActive`)
 
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |
 
+-------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
1 row in set (0.001 sec)
 
 
 
MariaDB [test]> select count(*) from cost;
 
sele+----------+
 
| count(*) |
 
+----------+
 
| 15678912 |
 
+----------+
 
1 row in set (2.639 sec)
 
 
 
MariaDB [test]> select version();
 
+-----------------+
 
| version()       |
 
+-----------------+
 
| 10.3.10-MariaDB |
 
+-----------------+
 
1 row in set (0.000 sec)

Halving the number of entries:

MariaDB [test]> shutdown;
 
Query OK, 0 rows affected (0.000 sec)
 
 
 
MariaDB [test]> Bye
 
 
 
$ sudo systemctl start mariadb.service
 
 
 
 
 
$  mysqldump -u root test > /dev/null
 
 
 
 
 
^C
 
[dan@volution systemd]$ mysql -u root -A test
 
Welcome to the MariaDB monitor.  Commands end with ; or \g.
 
Your MariaDB connection id is 9
 
Server version: 10.3.10-MariaDB MariaDB Server
 
 
 
Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.
 
 
 
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
 
 
 
MariaDB [test]> show global status like 'innodb_buffer_pool_pages%';
 
+----------------------------------+--------+
 
| Variable_name                    | Value  |
 
+----------------------------------+--------+
 
| Innodb_buffer_pool_pages_data    | 8142   |
 
| Innodb_buffer_pool_pages_dirty   | 3593   |
 
| Innodb_buffer_pool_pages_flushed | 140761 |
 
| Innodb_buffer_pool_pages_free    | 0      |
 
| Innodb_buffer_pool_pages_misc    | 50     |
 
| Innodb_buffer_pool_pages_total   | 8192   |
 
+----------------------------------+--------+
 
6 rows in set (0.002 sec)
 
 
 
MariaDB [test]> ANALYZE TABLE cost PERSISTENT FOR ALL;
 
 
 
^CCtrl-C -- query killed. Continuing normally.
 
+-----------+---------+----------+------------------+
 
| Table     | Op      | Msg_type | Msg_text         |
 
+-----------+---------+----------+------------------+
 
+-----------+---------+----------+------------------+
 
1 row in set (27 min 29.657 sec)

The memory usage of ANALYZE TABLE from before it started

while [ 1 ];  do  ps -uax  -q 29338  ; sleep 1; done
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 36.7  0.9 1414084 316468 ?      Ssl  14:49   4:25 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 36.7  0.9 1414084 316468 ?      Ssl  14:49   4:26 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 36.7  0.9 1414084 316468 ?      Ssl  14:49   4:26 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 36.7  0.9 1414084 316468 ?      Ssl  14:49   4:26 /usr/libexec/mysqld --basedir=/usr
 
..
 
..
 
..
 
(23 minutes later)
 
..
 
..
 
..
 
mysql    29338 32.9  1.1 1490884 360872 ?      Ssl  14:49  10:10 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.9  1.1 1490884 360872 ?      Ssl  14:49  10:10 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.9  1.1 1490884 360872 ?      Ssl  14:49  10:10 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.9  1.1 1490884 360872 ?      Ssl  14:49  10:11 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.9  1.1 1490884 360872 ?      Ssl  14:49  10:11 /usr/libexec/mysqld --basedir=/usr
 
...
 
..
 
..
 
5 minutes later:
 
..
 
..
 
..
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.5  1.1 1515460 389004 ?      Ssl  14:49  11:24 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.5  1.1 1515460 389004 ?      Ssl  14:49  11:25 /usr/libexec/mysqld --basedir=/usr
 
USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
 
mysql    29338 32.5  1.1 1515460 389004 ?      Ssl  14:49  11:25 /usr/libexec/mysqld --basedir=/usr

ANALYZE TABLE continued to run after 30minutes and failed to finish despite finishing in 30 seconds previously.

Memory use continued to over time.

Quote from coworker on 10.1.31-MariaDB-1~jessie running in x86-64 64G container:

run the `alter table xxx persistent for all` on dev-3 — runs for hours against a large table, and eventually mariadb just crashes / restarts without writing the stats. Frustrating to get these stats collected to see if it helps the query plan.

the container is getting killed after it exhausts its memory limits:

```"lastState": {

"terminated": { bq. "exitCode": 137, bq. "reason": "OOMKilled", bq. "startedAt": "2018-12-12T04:04:41Z", bq. "finishedAt": "2018-12-12T14:43:10Z", bq. "containerID": "docker://cc77db9f947369bfb4d6fb783cce841b30866460d0e57d1b1d3271777ec2beb2" bq. }

},```

must be a serious memory leak in the Analyze for it to use all ~64G of RAM when running the analyze (and no other activity happening in Maria)

 Comments   
Comment by Daniel Black [ 2018-12-13 ]

cost populated with:

INSERT INTO cost SELECT UUID(), IF(name='UNION',2,RAND()*5), name, IF(name='UNION',1,RAND()*5), RAND()*50 FROM mysql.help_topic;

several times before quite a few:

insert into cost select UUID(), snapshotActive,billingAccountName,period,cost FROM cost;

Comment by Elena Stepanova [ 2018-12-28 ]

We have several resource consumption issues filed in regard to ANALYZE with persistent statistics collection, most importantly MDEV-6181 (which was closed optimistically, as the root cause wasn't fixed, only the crash was), and MDEV-6529 which was spawned from it. I'll leave it to psergey to decide if he wants to keep this open as well.

Comment by Sergei Petrunia [ 2018-12-28 ]

High resource consumption is a known limitation of ANALYZE. But here, danblack mentions that

Halving the number of entries:
...
ANALYZE TABLE continued to run after 30minutes and failed to finish despite finishing in 30 seconds previously.

So it runs for much more time and consumes much more memory for a smaller dataset? It also continues to consume CPU, so this is not an "out of disk space in /tmp" issue. This looks like a different kind of bug to me.
elenst - could you or alice reproduce this effect - ANALYZE ... PERSISTENT FOR ALL running on a larger dataset is working while for halved dataset it is not?

Comment by Elena Stepanova [ 2018-12-28 ]

I hope that danblack can clarify what "halving the number of entires" means in this context. Except for this word, nothing in the description (neither the complaint itself, nor innodb buffer pool stats, nor the outcome) suggests that it's about an inexplicable behavior upon reducing the number of rows.

But if it's so anyway, I suppose danblack can provide the complete dataset and/or environment to reproduce it.

Comment by Daniel Black [ 2019-01-06 ]

mysqldump MDEV-17996.sql uploaded ftps://ftp.mariadb.com/

"halving the number of entries" was reducing the number of table rows by half. This non-completion may be another bug that just happened to manifest on a different dataset and wasn't intended to be the defining aspect of this bug report.

Generated at Thu Feb 08 08:40:43 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.