Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-28222

Performance regression in MariaDB 10.4 when iterating over many tables with large table_definition_cache, in comparison to MariaDB 10.3

    XMLWordPrintable

    Details

      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.

        Attachments

          Activity

            People

            Assignee:
            Unassigned Unassigned
            Reporter:
            valerii Valerii Kravchuk
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved:

                Git Integration

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