Bug #96340 Slow startup for mysql 8.0 with many tables due to the tablespace files scan
Submitted: 26 Jul 2019 12:13 Modified: 27 Nov 2019 19:25
Reporter: lalit Choudhary Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:8.0.17 OS:Any
Assigned to: CPU Architecture:Any

[26 Jul 2019 12:13] lalit Choudhary
Description:
With a large number of tables, the startup is slow since InnoDB is checking all the tablespace files on startup.

2019-07-26T11:39:25.273691Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'
2019-07-26T11:39:25.273849Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2019-07-26T11:39:35.507720Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 645/40002 files
2019-07-26T11:39:45.516326Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 1324/40002 files
2019-07-26T11:39:55.530244Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 2009/40002 files
2019-07-26T11:40:05.507102Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 2702/40002 files
2019-07-26T11:40:15.517350Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 3389/40002 files
2019-07-26T11:40:25.510736Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 4039/40002 files
.
.
2019-07-26T11:48:45.518910Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 38538/40002 files
2019-07-26T11:48:55.519284Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 39223/40002 files
2019-07-26T11:49:05.535676Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 39917/40002 files
2019-07-26T11:49:06.794193Z 1 [Note] [MY-012201] [InnoDB] Checked 40002 files
2019-07-26T11:49:06.794315Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 40004 files.

If we check the log (full log attached) scan performed using a single thread, it should be parallel. If there any way to make it parallel I do not find any related setting/variables in mysql documentation and it should be documented. 

How to repeat:
Repeatable test:
[mysqld]
innodb_buffer_pool_size=4G
log_error_verbosity = 3

create table using sysbench:total table 3000 Innodb tables.

sysbench /usr/share/sysbench/oltp_read_write.lua --mysql_storage_engine=innodb --table-size=1 --tables=40000 --mysql-db=test --mysql-user=msandbox --mysql-password=msandbox --mysql-socket=/tmp/mysql_sandbox22425.sock --threads=100 --time=9000 --report-interval=1 --events=0 --db-driver=mysql  prepare

The initial mysqld startup took ~10 mins  and after that, the startup is fast (~4 seconds)

---------------------
Initial startup:
-----------------
2019-07-26T11:39:25.273849Z 1 [Note] [MY-012204] [InnoDB] Scanning './'

2019-07-26T11:39:35.507720Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 645/40002 files

2019-07-26T11:39:45.516326Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 1324/40002 files

2019-07-26T11:39:55.530244Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 2009/40002 files

2019-07-26T11:49:05.535676Z 1 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 39917/40002 files

2019-07-26T11:49:06.794193Z 1 [Note] [MY-012201] [InnoDB] Checked 40002 files

2019-07-26T11:49:06.794315Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 40004 files.

2019-07-26T11:49:06.805235Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 4.000000G, instances = 8, chunk size =128.000000M 

2019-07-26T11:49:07.117037Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool

------------------
2nd startup 
-----------------
2019-07-26T11:55:11.762292Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'

2019-07-26T11:55:11.762380Z 1 [Note] [MY-012204] [InnoDB] Scanning './'

2019-07-26T11:55:13.499575Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 40004 files.

2019-07-26T11:55:13.511444Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 4.000000G, instances = 8, chunk size =128.000000M 

If I cleared OS cache, again next startup will take a long time for tablespace scanning.

echo 2 > /proc/sys/vm/drop_caches

Suggested fix:
The tablespace scan should be parallel if it's possible there should be documentation for this.
[26 Jul 2019 12:14] lalit Choudhary
mysql8 startup log

Attachment: mysql8_slow_startup.log (text/x-log), 11.54 KiB.

[26 Jul 2019 12:21] lalit Choudhary
description
[26 Jul 2019 13:03] lalit Choudhary
Mostly this issue evident on slow disk.
[29 Jul 2019 7:26] MySQL Verification Team
Hello Lalit,

Thank you for the report.
I attempted 2-3 times on a moderate test box but I'm not seeing any issues(probably need very slower disks to repeat the issue as you mentioned). Could you please share your environment details? If you can provide more information, feel free to add it to this bug and change the status back to 'Open'.  

- 8.0.17
 cat docs/INFO_SRC
commit: a5b2e523c881ab8c68fd0adb478a6232dd69e522
date: 2019-06-25 11:50:40 +0200
build-date: 2019-06-25 12:24:04 +0200
short: a5b2e52
branch: mysql-8.0.17-release

MySQL source 8.0.17

- 
rm -rf 96340/
bin/mysqld --initialize-insecure --basedir=$PWD --datadir=$PWD/96340 --log-error-verbosity=3
bin/mysqld --no-defaults --basedir=$PWD --datadir=$PWD/96340 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3333 --log-error=$PWD/96340/log.err --mysqlx-port=33330 --mysqlx-socket=/tmp/mysql_x_ushastry.sock --log-error-verbosity=3  --secure-file-priv=/tmp/ --innodb_buffer_pool_size=4G 2>&1 &

- sysbench

bin/sysbench --version
sysbench 1.1.0

bin/sysbench share/sysbench/oltp_read_write.lua --threads=100 --tables=40000 --table_size=1 --db-driver=mysql --mysql-db=test --mysql-user=ushastry --mysql-password=mysql123 --mysql-socket=/tmp/mysql_ushastry.sock prepare
.
Creating table 'sbtest39994'...
Inserting 1 records into 'sbtest39994'
Creating a secondary index on 'sbtest39994'...

- restarted mysqld
- excerpt from error log - looks like it took <2 sec

2019-07-29T07:02:57.375071Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'
2019-07-29T07:02:57.375154Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2019-07-29T07:02:58.608247Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 40004 files.
2019-07-29T07:02:58.613586Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 4.000000G, instances = 8, chunk size =128.000000M
2019-07-29T07:02:58.920557Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool

regards,
Umesh
[29 Jul 2019 7:34] MySQL Verification Team
Related - Bug #84025
[29 Jul 2019 11:17] lalit Choudhary
Hello Umesh,

Thank you for the test.

Indeed this issue with the slow disk. 

On fast storage, I see a huge improvement in startup time.

$ time ./start
.................................................... sandbox server started

real	0m52.168s
user	0m0.077s
sys	0m0.085s

2019-07-26T19:47:40.765129+05:30 1 [Note] [MY-012203] [InnoDB] Directories to scan './;./;./'
2019-07-26T19:47:40.765176+05:30 1 [Note] [MY-012204] [InnoDB] Scanning './'
2019-07-26T19:47:41.032187+05:30 1 [Note] [MY-012207] [InnoDB] Using 2 threads to scan the tablespace files
2019-07-26T19:47:51.003449+05:30 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 10418/50002 files
2019-07-26T19:48:01.003309+05:30 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 20824/50002 files
2019-07-26T19:48:11.003454+05:30 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 31460/50002 files
2019-07-26T19:48:21.003830+05:30 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 41899/50002 files
2019-07-26T19:48:28.903365+05:30 0 [Note] [MY-012201] [InnoDB] Checked 50002 files
2019-07-26T19:48:28.905649+05:30 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 50004 files.
2019-07-26T19:48:28.912415+05:30 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 4.000000G, instances = 8, chunk size =128.000000M

Saying this as I mentioned in the initial description there is no documentation on how  InnoDB Using parallel threads to scan the tablespace files while startup. it will be helpful for the user if we have such information documented in mysql document.

example:
[InnoDB] Using 2 threads to scan the tablespace files

Is selection of parallel thread done automatically by Innodb or do we have any variable to tune this setting?  We should have some documentation on mysql startup and how tablespace scan happens in parallel and how we can speedup with parallel threads.

So it would be great if you consider this as a documentation bug.
[29 Jul 2019 11:18] lalit Choudhary
documentation bug.
[29 Jul 2019 11:23] MySQL Verification Team
Thank you, observed the reported issue in VM environment.
Leaving category as is for now.

regards,
Umesh
[29 Jul 2019 11:25] MySQL Verification Team
Debian10 VM results

Attachment: 96340_8.0.17_vm.results (application/octet-stream, text), 9.16 KiB.

[29 Jul 2019 11:27] MySQL Verification Team
Looks like I overwrote your category change.
[31 Jul 2019 9:37] lalit Choudhary
As a workaround this problem,  Use General Tablespace to store these tables rather storing it as individual .ibd file per table. This will avoid the large number of tablespace scans which will speed-up the startup.
[31 Jul 2019 11:19] Sergiu Hlihor
This issue is a blocker for me. I have servers with large enterprise HDDs behind RAID controllers and large databases of 50+ TB per node, 50-100K tables. Since access patterns are range selects by primary key in every table and some data is periodically deleted once per year, the organization of table per file is mandatory for us given the storage.
However, since the table space never chances between restarts, scanning the full table space is not necessary. Is there any way to disable it by configuration parameters? To put the impact in perspective, with MySQL 5.6 or 5.7, a restart cycle took consistently less than 3 minutes. With MySQL 8, the restart cycle is anywhere between 40 and 90 minutes. With unpredictable restart cycles during maintenance restarts, service availability cannot be guaranteed anymore.

Also, the scan does not appear to be parallel at all. I see only one thread scanning the space and number of IO commands issued is about 200-300. My RAID array has an IO capacity of 2000-2500, thus requiring 10 to 12 threads to reach full usage. This would not solve the issue at all, but at least would mitigate some of the impact.

Environment is Ubuntu Server 18.04, storage is 12x 12TB HDDs in RAID 10. To fully observe the magnitude of the issue, you have to throttle the IO requests to about 200 per second / thread, or have an artificial IO added latency of 5ms.
[1 Aug 2019 10:49] lalit Choudhary
Also, I think this is a bug for 8.0, since on the same device 5.7 startup is fast very. So only issue with 8.0 version.
[1 Aug 2019 11:22] Stefan Hinz
Posted by developer:
 
This was (erroneously?) declared a documentation bug. I changed it to a code bug. If you think it is a documentation bug, though, please let us know what the docs should say to explain/resolve/work around the problem.
[13 Aug 2019 13:42] Peter Zaitsev
Hi Lalit,

Is startup significantly slower than with 5.7 ?
[13 Aug 2019 14:27] lalit Choudhary
Peter, 

for 8.0 it takes ~12 mins for mysql startup in my test with 40k tables whereas  
 for 5.7 it takes ~3 mins
[13 Aug 2019 17:33] Sunny Bains
The 5.7 startup can be faster because 8.x reverts the 5.7 changes where we wrote the open file descriptors in  the redo log on checkpoint. The scheme introduced in 5.7 was very buggy and it has a runtime cost (and lots of edge case bugs during recovery) and if you have lots of tables open and written to since the last checkpoint well good luck.

We decided to revert to 5.6 behavior to pay the cost on startup and will fix it properly later. 

The cost comes from opening the first N pages of every .ibd file and checking the table space ID to build the tablespace ID to filename map.

We are looking at several options (medium to long run) that will eliminate this cost altogether. The scanning for .ibd files in the directories is not the issue and is fast for both HDD and SSD etc.
[13 Aug 2019 17:36] Sunny Bains
Forgot to add, the tablespace scan is parallel but the heuristic kicks in at 50K files:

/** Validate the DD tablespace data against what's read during the
directory scan on startup. */
class Validate_files {
  using DD_tablespaces = std::vector<const dd::Tablespace *>;
  using Const_iter = DD_tablespaces::const_iterator;

  /* This is the maximum number of tablespaces that can be handled by
  a single thread.  If more than that, the tablespaces will be divided
  up between up to 8 threads. */
  const size_t MAX_TABLESPACES_PER_THREAD = 50000;

  /* If therea are more than MAX_TABLESPACES_PER_THREAD scanned, then
  the work will be distributed among up to this many parallel threads. */
  const size_t MAX_THREADS = 8;
[13 Aug 2019 18:28] Sergiu Hlihor
Actual production log

Attachment: Production.log (text/x-log), 22.58 KiB.

[13 Aug 2019 18:37] Sergiu Hlihor
I've attached a log from one of my production servers. RAID 10, 12x12TB, server idle, only database, Ubuntu 18.04, EXT4 partition. 

Restart cycle minimum of 40 minutes and worse, I see only one thread working although I have almost 90K tables. The real life data is way worse than what you guys get in testing.

If there is no fix on short term, why not having the threading configurable? I could easily decrease the restart cycle by a factor of 10 if I could throw multiple threads. 

Second, why not disabling completely the scan if having a clean shutdown? If all went well during shutdown, assumption should be that all files are still there.
[18 Aug 2019 12:27] Peter Zaitsev
Sunny,

Thank you for explanations. Have you considered writing some blog post about it, unless there is one already ?

I think it is very interesting case of choosing to roll back optimization you have made, but also it is not quite rollback as you made it parallel now.
[19 Aug 2019 23:29] Sunny Bains
We won't add a new config variable yet, but change some constants so that multiple threads are used at a lower threshold. Change the value from 50000 to 8000 and  the other proposed fix  is to  check only the header page instead of 3 pages we do currently.
[19 Aug 2019 23:31] Sunny Bains
Peter, Had not considered writing a blog post but will plan for one. Thanks for the suggestion.
[19 Aug 2019 23:36] Sunny Bains
On a host with slow HDD I created 50K tables with the proposed patch.

2019-08-19T23:24:01.871294Z 1 [Note] [MY-012205] [InnoDB] Files found so far: 46289 data files and 2 undo files
2019-08-19T23:24:02.490746Z 1 [Note] [MY-012206] [InnoDB] Found 50002 '.ibd' and 2 undo files
2019-08-19T23:24:02.490906Z 1 [Note] [MY-012207] [InnoDB] Using 4 threads to scan the tablespace files
2019-08-19T23:24:11.933488Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 1206/12500 files
2019-08-19T23:24:11.999470Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 398/12500 files
2019-08-19T23:24:12.306567Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 546/12500 files
2019-08-19T23:24:12.709359Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 468/12500 files
2019-08-19T23:24:21.872437Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 814/12500 files
2019-08-19T23:24:21.878414Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 782/12500 files
2019-08-19T23:24:21.965764Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 2784/12500 files
2019-08-19T23:24:22.355260Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 647/12500 files
2019-08-19T23:24:31.869091Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 3825/12500 files
2019-08-19T23:24:31.883373Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 1447/12500 files
2019-08-19T23:24:31.927162Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 1065/12500 files
2019-08-19T23:24:32.212470Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 1016/12500 files
2019-08-19T23:24:41.905120Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 2174/12500 files
2019-08-19T23:24:42.036511Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 1526/12500 files
2019-08-19T23:24:42.037974Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 1428/12500 files
2019-08-19T23:24:42.202930Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 4716/12500 files
2019-08-19T23:24:51.871488Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 1891/12500 files
2019-08-19T23:24:51.880739Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 2857/12500 files
2019-08-19T23:24:52.105336Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 5399/12500 files
2019-08-19T23:24:52.779745Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 2131/12500 files
2019-08-19T23:25:01.873952Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 2499/12500 files
2019-08-19T23:25:01.916684Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 2281/12500 files
2019-08-19T23:25:02.007113Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 3594/12500 files
2019-08-19T23:25:02.070638Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 6302/12500 files
2019-08-19T23:25:11.885646Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 2911/12500 files
2019-08-19T23:25:11.891455Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 4192/12500 files
2019-08-19T23:25:12.007876Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 7224/12500 files
2019-08-19T23:25:12.803591Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 2733/12500 files
2019-08-19T23:25:21.871243Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 3313/12500 files
2019-08-19T23:25:21.871572Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 3190/12500 files
2019-08-19T23:25:21.900671Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 4773/12500 files
2019-08-19T23:25:21.949638Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 8200/12500 files
2019-08-19T23:25:31.892896Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 5424/12500 files
2019-08-19T23:25:31.903858Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 9437/12500 files
2019-08-19T23:25:32.099673Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 3605/12500 files
2019-08-19T23:25:32.249530Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 3426/12500 files
2019-08-19T23:25:41.868472Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 10564/12500 files
2019-08-19T23:25:41.946926Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 5972/12500 files
2019-08-19T23:25:42.267684Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 3962/12500 files
2019-08-19T23:25:43.319287Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 3759/12500 files
2019-08-19T23:25:51.886063Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 4596/12500 files
2019-08-19T23:25:52.021380Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 6335/12500 files
2019-08-19T23:25:52.857867Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 11366/12500 files
2019-08-19T23:25:52.888001Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 4472/12500 files
2019-08-19T23:26:01.886040Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 5175/12500 files
2019-08-19T23:26:02.096185Z 0 [Note] [MY-012200] [InnoDB] Thread# 0 - Checked 11962/12500 files
2019-08-19T23:26:02.420704Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 6822/12500 files
2019-08-19T23:26:02.873136Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 5078/12500 files
2019-08-19T23:26:11.259431Z 0 [Note] [MY-012201] [InnoDB] Checked 12500 files
2019-08-19T23:26:12.050651Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 5825/12500 files
2019-08-19T23:26:12.302888Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 7255/12500 files
2019-08-19T23:26:12.891756Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 5805/12500 files
2019-08-19T23:26:21.908052Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 6715/12500 files
2019-08-19T23:26:21.996058Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 7637/12500 files
2019-08-19T23:26:22.982449Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 6766/12500 files
2019-08-19T23:26:31.891233Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 7708/12500 files
2019-08-19T23:26:32.036676Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 7937/12500 files
2019-08-19T23:26:32.889683Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 7707/12500 files
2019-08-19T23:26:41.895490Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 8565/12500 files
2019-08-19T23:26:41.907562Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 8283/12500 files
2019-08-19T23:26:42.981545Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 8771/12500 files
2019-08-19T23:26:51.879565Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 8655/12500 files
2019-08-19T23:26:51.883027Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 9705/12500 files
2019-08-19T23:26:52.879939Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 9571/12500 files
2019-08-19T23:27:01.876877Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 10629/12500 files
2019-08-19T23:27:02.098508Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 9016/12500 files
2019-08-19T23:27:02.930227Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 10619/12500 files
2019-08-19T23:27:11.868583Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 9584/12500 files
2019-08-19T23:27:11.905063Z 0 [Note] [MY-012200] [InnoDB] Thread# 2 - Checked 11597/12500 files
2019-08-19T23:27:12.889058Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 11517/12500 files
2019-08-19T23:27:20.469563Z 0 [Note] [MY-012201] [InnoDB] Checked 12500 files
2019-08-19T23:27:21.891936Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 10083/12500 files
2019-08-19T23:27:22.944906Z 0 [Note] [MY-012200] [InnoDB] Thread# 3 - Checked 12417/12500 files
2019-08-19T23:27:23.550626Z 0 [Note] [MY-012201] [InnoDB] Checked 12500 files
2019-08-19T23:27:31.890822Z 0 [Note] [MY-012200] [InnoDB] Thread# 1 - Checked 11812/12500 files
2019-08-19T23:27:35.305211Z 0 [Note] [MY-012201] [InnoDB] Checked 12500 files
2019-08-19T23:27:35.374562Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 50004 files.

This comes to about 3m30seconds. Down from 11mins without the patch. That maps to the 2 fewer pages we read to verify the space ID.
[20 Aug 2019 16:36] Sergiu Hlihor
Sunny, may I suggest different defaults?

The limit where threading could start kick in could be decreased to as low as 100 and threads could be easily increased to 16-24. Reasoning is the following: the access pattern is full random read. For 1-2 HDDs, issuing read requests through 24 threads will lead to larger response times per thread, but no throughput decrease since HDDs spend anyway most of the time doing seek. For large 12-24 disk HDD RAID arrays, this will scale almost linearly with number of disks.
For standard read oriented SSDs, you have a usable IO per thread of 2000-5000 and 100K-1000K when multithreaded, so more threading the better, as long as no significant OS locking.

Here are some estimates for 5K tables:
With 8000 limit, 8 threads as already proposed:
1 HDD, 40 files/s per thread.         Config => 1 thread => ~125s
12 HDD RAID, 40 files/s per thread    Config => 1 thread => ~125s 
1 SSD, ~500 files/s per thread        Config => 1 thread => ~10s

With 100 limit, 24 threads:
1 HDD, 40 files/s per thread.         Config => 1 thread => <125s due to NCQ
12 HDD RAID, 40 files/s per thread    Config => 1 thread => ~11s 
1 SSD, ~500 files/s per thread        Config => 1 thread => <1s

The only downside of decreasing the limits so aggressively is a temporary IO overload if using HDDs. Since this can shave minutes from database startup and bring back the restart cycle to the seconds range, I do not see any reason while such aggressive limits are not set, specially when databases are usually running on big HDD arrays or NVMe SSDs (which are sometimes capable of more than 1M IOPS).
[20 Aug 2019 16:39] Sergiu Hlihor
Correction, config would lead to 24 threads for second example from above, I cannot edit the comment
[20 Aug 2019 17:03] Sunny Bains
Proposed patch

Attachment: scan.diff (application/octet-stream, text), 5.63 KiB.

[20 Aug 2019 17:04] Sunny Bains
Sergiu, I've attached the draft patch.Should apply to 8.0.17 cleanly.  Can you please test it again with your suggested configuration  and share your numbers.
[20 Aug 2019 17:44] Sergiu Hlihor
Sunny,
I cannot do any test unfortunately. My slow servers are production environments where I cannot change MySQL build. And my local DEV environment is a little too fast (Intel Optane SSD). However estimated numbers are based on hardware capabilities, so cannot be wrong. You should be able to still see significant improvements down to 100. What I am trying to say is that, the finetuning will help for sure, but is still far from optimal value and only brings an improvement for large deployments. If optimal values are applied, then it will improve slightly also the small to medium deployments. 

Offtopic, looking in diff, I may suggest a slight code improvement:

size_t n_threads = ibd_files.size() / MAX_FILES_PER_THREAD;
could be: 
size_t n_threads = (ibd_files.size() / MAX_FILES_PER_THREAD) + 1;
No need then to check if value is zero and increment the n_threads after. And then the "if (n_threads > 0)" is also unnecessary since n_threads will always be greater than 0.
[8 Sep 2019 9:13] Manuel Mausz
I want to give some feedback about the patch: We just stumbled across this as we are preparing the MySQL 8 upgrade. We are running multiple servers for Webhosting purposes and right now each has about 100k InnoDB tables. Servers are (still) running on 15k SAS.

Without the patch startup time was about 30 minutes. With the patch as-is this got reduced to about 7 minutes. After changing MAX_SCAN_THREADS to 16 this got further reduced to about 6 minutes. Of course the I/O load is at 100% at this time. So overall the patch is a step in the right direction.
[27 Nov 2019 19:25] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.19 release, and here's the changelog entry:

Startup was slow on instances with a large number of tables due the
tablespace file scan that occurs at startup to retrieve space IDs. A
multithreaded scan was only initiated if the number of tablespace files
exceed 50,000, and three tablespace pages were read to retrieve a space
ID. To improve startup times, additional threads are now allocated for the
tablespace file scan, and only the first tablespace page is read to
retrieve a space ID. If a space ID is not found on the first page of the
tablespace, three pages are read to determine the space ID, as before.
[23 Mar 2020 23:08] Sergiu Hlihor
As feedback, it works like a charm less than 4 minutes per restart cycle instead of 30 minutes before upgrade (active treads observed to be increased from 2 to 16). Thank you!
[16 May 2020 3:32] Nikunj Gandhi
I have the same problem. My PC takes 8-9 min to start mysql. What configuration to set in my.cnf? I am using Mysql 8.0.20-0ubuntu0.19.10.1.

Please help !! It is a very long time to start.
[29 Sep 2023 7:51] MySQL Verification Team
Try this feature on 8.0:
https://dev.mysql.com/doc/refman/8.0/en/innodb-disabling-tablespace-path-validation.html