MySQL Bugs: #103743: slow mysql8 start with lots of _encrypted

Bug #103743	slow mysql8 start with lots of _encrypted_ tables
Submitted:	19 May 2021 21:07	Modified:	3 Jan 2022 6:51
Reporter:	roland schmidt	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	8.0.18, 8.0.25	OS:	CentOS
Assigned to:		CPU Architecture:	x86
Tags:	regression

Description:
With a large number of encrypted tables, the startup is slow since InnoDB is checking all the tablespace files on startup.
With a 10k tables database mysqld will start in about 8 minutes, while deactivating encryption on all tables will reduce start time to about 20 seconds.

With log level 3 logs are flowing tih below messages for each table
2021-05-19T20:38:18.305611Z 1 [Note] [MY-012976] [InnoDB] 8.0.18 started; log sequence number 1180957138
2021-05-19T20:38:18.333361Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80017'.
2021-05-19T20:38:18.827354Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2021-05-19T20:38:20.356437Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./testdb2/testtbl0.ibd successfully, encryption of this tablespace enabled.
...
2021-05-19T20:38:30.139971Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./testdb2/testtbl1485.ibd successfully, encryption of this tablespace enabled.
2021-05-19T20:38:30.153687Z 1 [Note] [MY-012350] [InnoDB] Validated 1492/10007 tablespaces so far.
...
2021-05-19T20:45:51.076141Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./testdb2/testtbl10000.ibd successfully, encryption of this tablespace enabled.
2021-05-19T20:45:51.167832Z 1 [Note] [MY-012356] [InnoDB] Validated 10007/10007  tablespaces
2021-05-19T20:45:51.358695Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80017'.

Tested on: 
- mysql8.0.17 - no issues
- mysql8.0.18 - slow start
- mysql8.0.23 - slow start
- mysql8.0.25 - slow start

There seems to be 2 thread (at least with mysql8.0.23) which are using up one CPU core. 
No IO wait usage/delay observed.
DB running on SSD drives.
All good on servers <=8.0.17 or very few tables.
Bug identified between 8.0.18-8.0.25 and mysql start time increase is related to number of tables (is bigger when more tables created).
Disabling encryption on all tables (with alter table) or deactivating  innodb_validate_tablespace_paths 
On bigger servers we have about 50k tables which could take 30-40 minutes which is a lot of time in case of a maintenance or if a servers reboots/crashes.

How to repeat:
Install mysql community server 8.0.18 (or latest 8.0.25)
Create a test database
Create 10k encrypted tables:
New tables are set default with encryption in our configuration.
mysql> show create table testtbl0;
+----------+----------------------------------------------------------------------------------------------------------------+
| Table    | Create Table                                                                                                   |
+----------+----------------------------------------------------------------------------------------------------------------+
| testtbl0 | CREATE TABLE `testtbl0` (
  `doi` varchar(50) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ENCRYPTION='Y' |
+----------+----------------------------------------------------------------------------------------------------------------+

No othercontent loaded
Stop mysql server by systemd
Start mysql server by systemd
Wait for it to start...

We introduced --validate_tablespace_paths in 8.0.21 to skip this step. See https://dev.mysql.com/doc/refman/8.0/en/innodb-disabling-tablespace-path-validation.html

Yes, as I mentioned above we already found that as a workaround but it has a downside of disabling that feature which behavior I understand was enabled by default on previous versions and might affect in some cases (few cases mostly maintenance/recovery related I belive).
"This WL introduces a new variable --innodb-validate-tablespace-paths := (ON | OFF) and the default will be ON to preserve existing behavior" (WL#14008)
Secondly it is strange that having unencrypted tables will not slow down the startup but only while using encryption.

Right. I read that in your comment. Just wanted to clarify the intent of the validation. The validation is not for checking encryption. Only to update the DD paths in case the files have been moved around.  The encryption validation is a side effect of that. It is not necessary to validate the encrypt files.

Hello roland,

Thank you for the report and test case.
Verified as described on 8.0.25 build.

regards,
Umesh

MySQL Server 8.0.25 test results

Attachment: 103743_8.0.25.results.txt (text/plain), 9.31 KiB.

- 8.0.17 - with the same steps

2021-05-20T09:51:10.329943Z 1 [Note] [MY-013018] [InnoDB] Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace. 128 are now active.
2021-05-20T09:51:10.331813Z 1 [Note] [MY-012976] [InnoDB] 8.0.17 started; log sequence number 247481562
2021-05-20T09:51:10.360195Z 1 [Note] [MY-011089] [Server] Data dictionary restarting version '80017'.
2021-05-20T09:51:11.018166Z 1 [Note] [MY-012357] [InnoDB] Reading DD tablespace files
2021-05-20T09:51:11.553014Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t0.ibd successfully, encryption of this tablespace enabled.
2021-05-20T09:51:11.554678Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t1.ibd successfully, encryption of this tablespace enabled.

.
.
.
2021-05-20T09:51:33.726117Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t14997.ibd successfully, encryption of this tablespace enabled.
2021-05-20T09:51:33.727457Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t14998.ibd successfully, encryption of this tablespace enabled.
2021-05-20T09:51:33.728863Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t14999.ibd successfully, encryption of this tablespace enabled.
2021-05-20T09:51:33.730536Z 1 [Note] [MY-012227] [InnoDB] Read encryption metadata from ./test/t15000.ibd successfully, encryption of this tablespace enabled.
2021-05-20T09:51:33.730565Z 1 [Note] [MY-012356] [InnoDB] Validated 15007/15007  tablespaces
2021-05-20T09:51:33.731619Z 0 [Note] [MY-011946] [InnoDB] Loading buffer pool(s) from /home/umshastr/work/binaries/ga/mysql-8.0.17/103743/ib_buffer_pool
2021-05-20T09:51:33.749769Z 1 [Note] [MY-010006] [Server] Using data dictionary with version '80017'.
2021-05-20T09:51:33.870571Z 0 [Note] [MY-010902] [Server] Thread priority attribute setting in Resource Group SQL shall be ignored due to unsupported platform or insufficient privilege.
2021-05-20T09:51:33.899057Z 0 [Note] [MY-012487] [InnoDB] DDL log recovery : begin
2021-05-20T09:51:33.899105Z 0 [Note] [MY-012488] [InnoDB] DDL log recovery : end
2021-05-20T09:51:33.913893Z 0 [Note] [MY-012922] [InnoDB] Waiting for purge to start
2021-05-20T09:51:34.003656Z 0 [Note] [MY-010913] [Server] You have not provided a mandatory server-id. Servers in a replication topology must have unique server-ids. Please refer to the proper server start-up parameters documentation.
2021-05-20T09:51:34.064998Z 0 [Note] [MY-010182] [Server] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2021-05-20T09:51:34.065013Z 0 [Note] [MY-010304] [Server] Skipping generation of SSL certificates as certificate files are present in data directory.
2021-05-20T09:51:34.068360Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2021-05-20T09:51:34.068438Z 0 [Note] [MY-010308] [Server] Skipping generation of RSA key pair through --sha256_password_auto_generate_rsa_keys as key files are present in data directory.
2021-05-20T09:51:34.068451Z 0 [Note] [MY-010308] [Server] Skipping generation of RSA key pair through --caching_sha2_password_auto_generate_rsa_keys as key files are present in data directory.
2021-05-20T09:51:34.071221Z 0 [Note] [MY-010252] [Server] Server hostname (bind-address): '*'; port: 3333
2021-05-20T09:51:34.071253Z 0 [Note] [MY-010253] [Server] IPv6 is available.
2021-05-20T09:51:34.071268Z 0 [Note] [MY-010264] [Server]   - '::' resolves to '::';
2021-05-20T09:51:34.071321Z 0 [Note] [MY-010251] [Server] Server socket created on IP: '::'.
2021-05-20T09:51:34.129305Z 0 [Note] [MY-011025] [Repl] Failed to start slave threads for channel ''.
2021-05-20T09:51:34.130605Z 4 [Note] [MY-010051] [Server] Event Scheduler: scheduler thread started with id 4
2021-05-20T09:51:34.211710Z 0 [System] [MY-010931] [Server] /home/umshastr/work/binaries/ga/mysql-8.0.17/bin/mysqld: ready for connections. Version: '8.0.17'  socket: '/tmp/mysql_ushastry.sock'  port: 3333  MySQL Community Server - GPL.
2021-05-20T09:51:34.328149Z 0 [Note] [MY-011240] [Server] Plugin mysqlx reported: 'Using SSL configuration from MySQL Server'
2021-05-20T09:51:34.330652Z 0 [Note] [MY-011243] [Server] Plugin mysqlx reported: 'Using OpenSSL for TLS connections'
2021-05-20T09:51:34.330704Z 0 [Note] [MY-011332] [Server] Plugin mysqlx reported: 'IPv6 is available'
2021-05-20T09:51:34.332651Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. bind-address: '::' port: 33330'
2021-05-20T09:51:34.332666Z 0 [Note] [MY-011323] [Server] Plugin mysqlx reported: 'X Plugin ready for connections. socket: '/tmp/mysql_x_ushastry.sock''
2021-05-20T09:51:34.332684Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/tmp/mysql_x_ushastry.sock' bind-address: '::' port: 33330
2021-05-20T09:51:36.448949Z 0 [Note] [MY-011946] [InnoDB] Buffer pool(s) load completed at 210520 11:51:36

Hi,

do you have an estimate for a fix?

thanks

Please note that this is already fixed in 8.0.27 under the heading of: Bug#32846656 - 8.0.22 INSTANCE TAKES 7+ HOURS TO START WITH 126K INNODB TABLES

Fixed in 8.0.27 release:

Startup on an instance with thousands of tables took an excessive amount
of time due a large amount of traffic on the error logging subsystem.