[MDEV-24975] Server consumes extra 4G memory upon querying INFORMATION_SCHEMA.OPTIIMIZER_TRACE - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Critical
Resolution: Fixed
Affects Version/s: 10.4(EOL), 10.5, 10.6
Fix Version/s: 10.4.19, 10.5.10
Component/s: Information Schema
Labels:
- regression

Description

Queries involving INFORMATION_SCHEMA.OPTIMIZER_TRACE table (even an empty one and/or with disabled optimizer_trace) take quite long time and make the server memory consumption temporarily jump ~4G up for each query and instance of the table. That is, if the query joins OPTIMIZER_TRACE table with itself, it's 8G, if it joins twice, it's 12G. After the job is done, the consumption drops back, but these peaks can apparently cause OOM on small machines.

10.4 ad0f0d2b1 non-debug
MariaDB [test]> SELECT COUNT(*) FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE;
+----------+
\| COUNT(*) \|
+----------+
\| 0 \|
+----------+
1 row in set (0.998 sec)

MariaDB [test]> SELECT COUNT(*) FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE;
+----------+
\| COUNT(*) \|
+----------+
\| 0 \|
+----------+
1 row in set (0.998 sec)

MariaDB [test]> SELECT COUNT(*) FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE;
+----------+
\| COUNT(*) \|
+----------+
\| 0 \|
+----------+
1 row in set (0.987 sec)

4109823 elenst    20   0 1758144  80088  19976 S   0.0   0.1   0:05.14 mysqld

4109823 elenst    20   0 5952452   3.6g  19976 S  73.5   3.8   0:05.89 mysqld

4109823 elenst    20   0 5952452   3.6g  19976 S 101.0   3.8   0:06.90 mysqld

4109823 elenst    20   0 5952452   3.7g  19976 S  99.0   4.0   0:07.91 mysqld

4109823 elenst    20   0 1758144  80088  19976 S  19.8   0.1   0:08.11 mysqld

MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3;

Empty set (2.792 sec)

MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3;

Empty set (2.765 sec)

MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3;

Empty set (3.185 sec)

4109823 elenst    20   0 1758144  80088  19976 S   0.0   0.1   0:08.15 mysqld

4109823 elenst    20   0 9908.9m   4.3g  19976 S  86.1   4.5   0:09.02 mysqld

4109823 elenst    20   0   13.7g   9.4g  19976 S 100.0   9.9   0:10.04 mysqld

4109823 elenst    20   0 5952452 609764  19976 S 100.0   0.6   0:11.05 mysqld

4109823 elenst    20   0 9908.9m   5.5g  19976 S  98.0   5.8   0:12.05 mysqld

4109823 elenst    20   0   13.7g  10.6g  19976 S 102.0  11.3   0:13.07 mysqld

4109823 elenst    20   0 5952452   1.7g  19976 S  98.0   1.8   0:14.07 mysqld

4109823 elenst    20   0 9908.9m   5.9g  19976 S 100.0   6.2   0:15.08 mysqld

4109823 elenst    20   0   13.7g  10.4g  19976 S 100.0  11.0   0:16.09 mysqld

4109823 elenst    20   0 1758144  80196  19976 S  75.5   0.1   0:16.86 mysqld

4109823 elenst    20   0 1758144  80196  19976 S   0.0   0.1   0:16.86 mysqld

Reproducible on 10.4-10.6.
The test case is not applicable to 10.3 due to the use of optimizer_trace.

Most likely the problem was introduced by this commit:

commit e64084d5a3a72462fa6263d1d0a86e72c0ba0d47

Author: Sergei Golubchik

Date:   Sat Aug 1 13:12:50 2020 +0200

    MDEV-21201 No records produced in information_schema query, depending on projection

I can only confirm that it's reproducible on 10.4 after the merge containing the commit, and not reproducible before; but since the commit was in 10.3, 10.3 doesn't have optimizer trace, and I couldn't reproduce it on other information_schema tables, I couldn't check the exact commit.

Attachments

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2021-02-25 01:09

Elena Stepanova made changes - 2021-02-25 01:14

Field	Original Value	New Value
Description	Queries involving INFORMATION_SCHEMA.OPTIMIZER_TRACE table (even an empty one and/or with disabled optimizer_trace) take quite long time and make the server memory consumption temporarily jump ~4G up for each query and instance of the table. That is, if the query joins OPTIMIZER_TRACE table with itself, it's 8G, if it joins twice, it's 12G. After the job is done, the consumption drops back, but these peaks can apparently cause OOM. {code:sql\|title=10.4 ad0f0d2b1 non-debug} MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.998 sec) MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.998 sec) MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.987 sec) {code} {noformat} 4109823 elenst 20 0 1758144 80088 19976 S 0.0 0.1 0:05.14 mysqld 4109823 elenst 20 0 5952452 3.6g 19976 S 73.5 3.8 0:05.89 mysqld 4109823 elenst 20 0 5952452 3.6g 19976 S 101.0 3.8 0:06.90 mysqld 4109823 elenst 20 0 5952452 3.7g 19976 S 99.0 4.0 0:07.91 mysqld 4109823 elenst 20 0 1758144 80088 19976 S 19.8 0.1 0:08.11 mysqld {noformat} {code:sql} MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (2.792 sec) MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (2.765 sec) MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (3.185 sec) {code} {noformat} 4109823 elenst 20 0 1758144 80088 19976 S 0.0 0.1 0:08.15 mysqld 4109823 elenst 20 0 9908.9m 4.3g 19976 S 86.1 4.5 0:09.02 mysqld 4109823 elenst 20 0 13.7g 9.4g 19976 S 100.0 9.9 0:10.04 mysqld 4109823 elenst 20 0 5952452 609764 19976 S 100.0 0.6 0:11.05 mysqld 4109823 elenst 20 0 9908.9m 5.5g 19976 S 98.0 5.8 0:12.05 mysqld 4109823 elenst 20 0 13.7g 10.6g 19976 S 102.0 11.3 0:13.07 mysqld 4109823 elenst 20 0 5952452 1.7g 19976 S 98.0 1.8 0:14.07 mysqld 4109823 elenst 20 0 9908.9m 5.9g 19976 S 100.0 6.2 0:15.08 mysqld 4109823 elenst 20 0 13.7g 10.4g 19976 S 100.0 11.0 0:16.09 mysqld 4109823 elenst 20 0 1758144 80196 19976 S 75.5 0.1 0:16.86 mysqld 4109823 elenst 20 0 1758144 80196 19976 S 0.0 0.1 0:16.86 mysqld {noformat} Reproducible on 10.4-10.6. The test case is not applicable to 10.3 due to the use of optimizer_trace. Most likely the problem was introduced by this commit: {noformat} commit e64084d5a3a72462fa6263d1d0a86e72c0ba0d47 Author: Sergei Golubchik Date: Sat Aug 1 13:12:50 2020 +0200 ~~MDEV-21201~~ No records produced in information_schema query, depending on projection {noformat} _I can only confirm that it's reproducible on 10.4 after the merge containing the commit, and not reproducible before; but since the commit was in 10.3, 10.3 doesn't have optimizer trace, and I couldn't reproduce it on other information_schema tables, I couldn't check the exact commit._	Queries involving INFORMATION_SCHEMA.OPTIMIZER_TRACE table (even an empty one and/or with disabled optimizer_trace) take quite long time and make the server memory consumption temporarily jump ~4G up for each query and instance of the table. That is, if the query joins OPTIMIZER_TRACE table with itself, it's 8G, if it joins twice, it's 12G. After the job is done, the consumption drops back, but these peaks can apparently cause OOM on small machines. {code:sql\|title=10.4 ad0f0d2b1 non-debug} MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.998 sec) MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.998 sec) MariaDB [test]> SELECT COUNT() FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE; +----------+ \| COUNT() \| +----------+ \| 0 \| +----------+ 1 row in set (0.987 sec) {code} {noformat} 4109823 elenst 20 0 1758144 80088 19976 S 0.0 0.1 0:05.14 mysqld 4109823 elenst 20 0 5952452 3.6g 19976 S 73.5 3.8 0:05.89 mysqld 4109823 elenst 20 0 5952452 3.6g 19976 S 101.0 3.8 0:06.90 mysqld 4109823 elenst 20 0 5952452 3.7g 19976 S 99.0 4.0 0:07.91 mysqld 4109823 elenst 20 0 1758144 80088 19976 S 19.8 0.1 0:08.11 mysqld {noformat} {code:sql} MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (2.792 sec) MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (2.765 sec) MariaDB [test]> SELECT 1 FROM INFORMATION_SCHEMA.OPTIMIZER_TRACE t1, INFORMATION_SCHEMA.OPTIMIZER_TRACE t2, INFORMATION_SCHEMA.OPTIMIZER_TRACE t3; Empty set (3.185 sec) {code} {noformat} 4109823 elenst 20 0 1758144 80088 19976 S 0.0 0.1 0:08.15 mysqld 4109823 elenst 20 0 9908.9m 4.3g 19976 S 86.1 4.5 0:09.02 mysqld 4109823 elenst 20 0 13.7g 9.4g 19976 S 100.0 9.9 0:10.04 mysqld 4109823 elenst 20 0 5952452 609764 19976 S 100.0 0.6 0:11.05 mysqld 4109823 elenst 20 0 9908.9m 5.5g 19976 S 98.0 5.8 0:12.05 mysqld 4109823 elenst 20 0 13.7g 10.6g 19976 S 102.0 11.3 0:13.07 mysqld 4109823 elenst 20 0 5952452 1.7g 19976 S 98.0 1.8 0:14.07 mysqld 4109823 elenst 20 0 9908.9m 5.9g 19976 S 100.0 6.2 0:15.08 mysqld 4109823 elenst 20 0 13.7g 10.4g 19976 S 100.0 11.0 0:16.09 mysqld 4109823 elenst 20 0 1758144 80196 19976 S 75.5 0.1 0:16.86 mysqld 4109823 elenst 20 0 1758144 80196 19976 S 0.0 0.1 0:16.86 mysqld {noformat} Reproducible on 10.4-10.6. The test case is not applicable to 10.3 due to the use of optimizer_trace. Most likely the problem was introduced by this commit: {noformat} commit e64084d5a3a72462fa6263d1d0a86e72c0ba0d47 Author: Sergei Golubchik Date: Sat Aug 1 13:12:50 2020 +0200 ~~MDEV-21201~~ No records produced in information_schema query, depending on projection {noformat} _I can only confirm that it's reproducible on 10.4 after the merge containing the commit, and not reproducible before; but since the commit was in 10.3, 10.3 doesn't have optimizer trace, and I couldn't reproduce it on other information_schema tables, I couldn't check the exact commit._

Elena Stepanova made changes - 2021-02-25 01:15

Summary

Server consumes extra 4G memory upon usage of INFORMATION_SCHEMA.OPTIIMIZER_TRACE

Server consumes extra 4G memory upon querying INFORMATION_SCHEMA.OPTIIMIZER_TRACE

Sergei Golubchik made changes - 2021-03-01 13:20

Priority

Major [ 3 ]

Critical [ 2 ]

Sergei Golubchik made changes - 2021-03-07 13:11

Status

Open [ 1 ]

In Progress [ 3 ]

Sergei Golubchik made changes - 2021-03-07 13:11

Status

In Progress [ 3 ]

Stalled [ 10000 ]

Sergei Golubchik made changes - 2021-03-08 14:50

Fix Version/s		10.4.19 [ 25205 ]
Fix Version/s		10.5.10 [ 25204 ]
Fix Version/s	10.4 [ 22408 ]
Fix Version/s	10.5 [ 23123 ]
Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2021-12-06 21:53

Workflow

MariaDB v3 [ 119495 ]

MariaDB v4 [ 158955 ]

People

Assignee:: Sergei Golubchik

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2021-02-25 01:09

Updated:: 2021-03-08 16:47

Resolved:: 2021-03-08 14:50

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server