Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Cannot Reproduce
-
10.4.17, 10.4.25
-
macOS 10.13.6, Windows (suspected)
Description
Consider the following MTR test case:
Yuliyas-MacBook-Air:mysql-test Valerii$ cat suite/innodb/t/tdc.test
|
source include/have_innodb.inc;
|
set default_storage_engine=innodb;
|
delimiter ||;
|
set use_stat_tables=NEVER||
|
for i in 1..50000 do execute immediate concat('create table if not exists t_', i,' as select ', i, ' as a'); end for||
|
set global table_definition_cache=50000||
|
select @@table_definition_cache||
|
flush tables||
|
flush status||
|
# load tables into cache
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
show status like 'open%'||
|
# verify that they're in the cache now
|
select now()||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
select now()||
|
show status like 'open%'||
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=500000||
|
select @@table_definition_cache||
|
flush status||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
show status like 'open%'||
|
select now()||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
select now()||
|
show status like 'open%'||
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=default||
|
show profiles||
|
show profile all for query 1||
|
show profile all for query 2||
|
select now()||
|
for i in 1..50000 do execute immediate concat('drop table t_', i); end for||
|
select now()||
|
that is essentially https://jira.mariadb.org/secure/attachment/62808/flush_benchmark_1.test with few selects added to measure time spent on second UPDATE and DROP TABLE steps.
On 10.3 I get:
Yuliyas-MacBook-Air:mysql-test Valerii$ ./mtr --suite=innodb tdc
|
Logging: ./mtr --suite=innodb tdc
|
VS config:
|
vardir: /Users/Valerii/dbs/maria10.3/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory '/Users/Valerii/dbs/maria10.3/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.3.35-MariaDB
|
- SSL connections supported
|
- binaries built with wsrep patch
|
Collecting tests...
|
Installing system database...
|
 |
==============================================================================
|
 |
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
 |
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
set default_storage_engine=innodb;
|
set use_stat_tables=NEVER||
|
for i in 1..50000 do execute immediate concat('create table if not exists t_', i,' as select ', i, ' as a'); end for||
|
set global table_definition_cache=50000||
|
select @@table_definition_cache||
|
@@table_definition_cache
|
50000
|
flush tables||
|
flush status||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 7
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 150138
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 50000
|
Opened_views 0
|
select now()||
|
now()
|
2022-04-02 17:16:09
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
select now()||
|
now()
|
2022-04-02 17:19:13
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 7
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 150138
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 100000
|
Opened_views 0
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=500000||
|
select @@table_definition_cache||
|
@@table_definition_cache
|
500000
|
flush status||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 7
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 200138
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 50000
|
Opened_views 0
|
select now()||
|
now()
|
2022-04-02 17:22:53
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
worker[1] Test still running: innodb.tdc
|
select now()||
|
now()
|
2022-04-02 17:25:58
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 7
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 200138
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 100000
|
Opened_views 0
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=default||
|
show profiles||
|
Query_ID Duration Query
|
1 0.17661200 flush tables
|
2 0.22418900 flush tables
|
show profile all for query 1||
|
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
|
Starting 0.176541 0.149710 0.024630 0 94 NULL NULL NULL
|
Query end 0.000013 0.000008 0.000005 0 0 <unknown> sql_parse.cc 6085
|
Commit 0.000005 0.000003 0.000002 0 0 0 <unknown> sql_parse.cc 6149
|
Closing tables 0.000004 0.000003 0.000001 0 0 <unknown> sql_base.cc 728
|
Commit_implicit 0.000003 0.000003 0.000000 0 0 <unknown> sql_parse.cc 6193
|
Starting cleanup 0.000004 0.000002 0.000001 0 <unknown> sql_parse.cc 6221
|
Freeing items 0.000005 0.000004 0.000001 0 0 <unknown> sql_parse.cc 7887
|
Updating status 0.000022 0.000008 0.000015 0 0 <unknown> sql_parse.cc 2405
|
Reset for next command 0.000015 0.000014 0.000001 0 <unknown> sql_parse.cc 2429
|
show profile all for query 2||
|
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
|
Starting 0.224081 0.168832 0.052962 0 131 NULL NULL NULL
|
Query end 0.000016 0.000009 0.000007 0 0 <unknown> sql_parse.cc 6085
|
Commit 0.000009 0.000005 0.000004 0 0 0 <unknown> sql_parse.cc 6149
|
Closing tables 0.000008 0.000005 0.000003 0 0 <unknown> sql_base.cc 728
|
Commit_implicit 0.000007 0.000004 0.000002 0 0 <unknown> sql_parse.cc 6193
|
Starting cleanup 0.000006 0.000003 0.000002 0 <unknown> sql_parse.cc 6221
|
Freeing items 0.000008 0.000007 0.000003 0 0 <unknown> sql_parse.cc 7887
|
Updating status 0.000031 0.000010 0.000020 0 0 <unknown> sql_parse.cc 2405
|
Reset for next command 0.000023 0.000020 0.000003 0 <unknown> sql_parse.cc 2429
|
select now()||
|
now()
|
2022-04-02 17:25:59
|
for i in 1..50000 do execute immediate concat('drop table t_', i); end for||
|
select now()||
|
now()
|
2022-04-02 17:37:05
|
innodb.tdc 'innodb' [ pass ] 2012753
|
--------------------------------------------------------------------------
|
The servers were restarted 0 times
|
Spent 2012.753 of 2020 seconds executing testcases
|
 |
Completed: All 1 tests were successful.
|
It means that total time to run is 2012 seconds, of them:
- second UPDATE with smaller table_definition_cache takes 3 minutes and 4 seconds
- second UPDATE with larger table_definition_cache takes 3 minutes and 5 seconds (no real difference)
- DROP of 50000 tables with larger table_definition_cache takes 11 minutes 6 seconds.
Now, with recent 10.4 build from GitHub source, on the same system I get:
Yuliyas-MacBook-Air:mysql-test Valerii$ ./mtr --suite=innodb tdc
|
Logging: ./mtr --suite=innodb tdc
|
VS config:
|
vardir: /Users/Valerii/dbs/maria10.4/mysql-test/var
|
Checking leftover processes...
|
Removing old var directory...
|
Creating var directory '/Users/Valerii/dbs/maria10.4/mysql-test/var'...
|
Checking supported features...
|
MariaDB Version 10.4.25-MariaDB
|
- SSL connections supported
|
Collecting tests...
|
Installing system database...
|
 |
==============================================================================
|
 |
TEST RESULT TIME (ms) or COMMENT
|
--------------------------------------------------------------------------
|
 |
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
|
set default_storage_engine=innodb;
|
set use_stat_tables=NEVER||
|
for i in 1..50000 do execute immediate concat('create table if not exists t_', i,' as select ', i, ' as a'); end for||
|
set global table_definition_cache=50000||
|
select @@table_definition_cache||
|
@@table_definition_cache
|
50000
|
flush tables||
|
flush status||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
worker[1] Test still running: innodb.tdc
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 6
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 150141
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 50000
|
Opened_views 0
|
select now()||
|
now()
|
2022-04-02 18:11:57
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
select now()||
|
now()
|
2022-04-02 18:15:16
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 6
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 150141
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 100000
|
Opened_views 0
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=500000||
|
select @@table_definition_cache||
|
@@table_definition_cache
|
500000
|
flush status||
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 6
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 200141
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 50000
|
Opened_views 0
|
select now()||
|
now()
|
2022-04-02 18:18:49
|
for i in 1..50000 do execute immediate concat('update t_', i,' set a=a+1'); end for||
|
select now()||
|
now()
|
2022-04-02 18:21:53
|
show status like 'open%'||
|
Variable_name Value
|
Open_files 6
|
Open_streams 0
|
Open_table_definitions 50000
|
Open_tables 421
|
Opened_files 200141
|
Opened_plugin_libraries 0
|
Opened_table_definitions 50000
|
Opened_tables 100000
|
Opened_views 0
|
set session profiling = ON||
|
flush tables||
|
set session profiling = OFF||
|
set global table_definition_cache=default||
|
show profiles||
|
Query_ID Duration Query
|
1 0.16105500 flush tables
|
2 0.22038200 flush tables
|
show profile all for query 1||
|
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
|
Starting 0.160942 0.134530 0.023944 0 338 1920 0 NULL NULL NULL
|
Query end 0.000011 0.000005 0.000005 0 0 <unknown> sql_parse.cc 6218
|
Commit 0.000005 0.000004 0.000002 0 0 0 <unknown> sql_parse.cc 6264
|
Closing tables 0.000004 0.000003 0.000001 0 0 <unknown> sql_base.cc 882
|
Commit_implicit 0.000004 0.000003 0.000001 0 0 <unknown> sql_parse.cc 6303
|
Starting cleanup 0.000004 0.000002 0.000001 0 <unknown> sql_parse.cc 6331
|
Freeing items 0.000005 0.000005 0.000001 0 0 <unknown> sql_parse.cc 8028
|
Updating status 0.000033 0.000009 0.000024 0 0 <unknown> sql_parse.cc 2452
|
Reset for next command 0.000047 0.000022 0.000019 0 <unknown> sql_parse.cc 2476
|
show profile all for query 2||
|
Status Duration CPU_user CPU_system Context_voluntary Context_involuntary Block_ops_in Block_ops_out Messages_sent Messages_received Page_faults_major Page_faults_minor Swaps Source_function Source_file Source_line
|
Starting 0.220290 0.158555 0.069353 74 1296 173 0 NULL NULL NULL
|
Query end 0.000011 0.000006 0.000004 0 0 <unknown> sql_parse.cc 6218
|
Commit 0.000005 0.000003 0.000002 0 0 0 <unknown> sql_parse.cc 6264
|
Closing tables 0.000004 0.000003 0.000000 0 0 <unknown> sql_base.cc 882
|
Commit_implicit 0.000003 0.000003 0.000001 0 0 <unknown> sql_parse.cc 6303
|
Starting cleanup 0.000004 0.000003 0.000001 0 <unknown> sql_parse.cc 6331
|
Freeing items 0.000005 0.000004 0.000001 0 0 <unknown> sql_parse.cc 8028
|
Updating status 0.000021 0.000016 0.000014 0 0 <unknown> sql_parse.cc 2452
|
Reset for next command 0.000039 0.000017 0.000013 0 <unknown> sql_parse.cc 2476
|
select now()||
|
now()
|
2022-04-02 18:21:53
|
for i in 1..50000 do execute immediate concat('drop table t_', i); end for||
|
worker[1] Test still running: innodb.tdc
|
select now()||
|
now()
|
2022-04-02 18:33:05
|
innodb.tdc 'innodb' [ pass ] 3318735
|
--------------------------------------------------------------------------
|
The servers were restarted 0 times
|
Spent 3318.735 of 3296 seconds executing testcases
|
 |
Completed: All 1 tests were successful.
|
It means that total time to run is 3319 seconds (1,5 times more), of them:
- second UPDATE with smaller table_definition_cache takes 3 minutes and 19 seconds
- second UPDATE with larger table_definition_cache takes 3 minutes and 4 seconds (even faster)
- DROP of 50000 tables with larger table_definition_cache takes 11 minutes 12 seconds.
So, it seems most of the difference is coming either from the first runs of UPDATE, or from CREATE TABLE with table_definition_cache of 50K.
In any case, 10.4 being slower than 10.3 with large table_definition_cache (both 50K and 500K are "large" for this purpose) while "iterating" over many (50K, 100K, 500K) tables was reported elsewhere for Windows environment as well. This performance regression is something to study.