Startup was very slow on instances with a large number of tables

MySQL & MariaDB
1

Description:
Servidor Windows Server 2012 R2, 128 GB
MySQL 8.0.30
Storage 12.000 Iops
Cluster with 490 schemas with 1.31TB in size
All schemas have month partitioned tables
Tables (87.830) + Partitions (221.612) = 309.442

MySQL very very slow to start, takes more than 33 minutes to start.

This issue did not occur in 5.5 and 5.6.

I opened a ticket on oracle but they didn’t consider a mistake even another user who had already opened it and said they would fix it in 8.0.19 (MySQL Bugs: #96340: Slow startup for mysql 8.0 with many tables due to the tablespace files scan) but it seems that the problem persists .

I was using 5.7 and had the same problem, I read the 1 Billion tables percona article and decided to migrate to 8, but MySQL is still slow to start.

2

Do your MySQL log files show anything?

1 Like
3

Nothing strange in the log.

Some variables that I changed to see if it improves and no results.

innodb_io_capacity_max=20000
innodb_io_capacity=5000
innodb_buffer_pool_instances=32
tablespace_definition_cache = 524288
schema_definition_cache = 524288
table_definition_cache = 524288
table_open_cache=524288
table_open_cache_instances=32
open-files-limit=800000

Follow the log

2022-10-09T15:18:44.905227Z 0 [Warning] [MY-010915] [Server] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release.
2022-10-09T15:18:44.906807Z 0 [System] [MY-010116] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld (mysqld 8.0.30) starting as process 17404
2022-10-09T15:18:47.597287Z 0 [Warning] [MY-013907] [InnoDB] Deprecated configuration parameters innodb_log_file_size and/or innodb_log_files_in_group have been used to compute innodb_redo_log_capacity=8589934592. Please use innodb_redo_log_capacity instead.
2022-10-09T15:18:48.281251Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-10-09T15:43:44.420554Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-10-09T15:51:51.901950Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2022-10-09T15:51:51.903356Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-10-09T15:51:52.273125Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '::' port: 8800
2022-10-09T15:51:52.273324Z 0 [System] [MY-010931] [Server] C:\Program Files\MySQL\MySQL Server 8.0\bin\mysqld: ready for connections. Version: '8.0.30'  socket: ''  port: 9999  MySQL Community Server - GPL.
1 Like
4

Can you show us from PMM the graphs for disk reads, and from MySQL InnoDB Details? Would be interesting to see what MySQL busy reading/processing

1 Like
5

From what I observed, the delay is in checking the .ibd files, in some cases it takes more than 40ms per file.

The bug is the same as this one: MySQL Bugs: #96340: Slow startup for mysql 8.0 with many tables due to the tablespace files scan

PMM client does not work on Windows servers.

=====================================
2022-10-10 15:15:24 0x3690 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 24 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 4515949 srv_active, 0 srv_shutdown, 52293 srv_idle
srv_master_thread log flush and writes: 61891
----------
SEMAPHORES
----------

OS WAIT ARRAY INFO: signal count 2621810551
RW-shared spins 0, rounds 4017469474, OS waits 2112259800
RW-excl spins 0, rounds 77491508869, OS waits 2266297482
RW-sx spins 1784032, rounds 37981009, OS waits 343555
Spin rounds per wait: 4017469474.00 RW-shared, 77491508869.00 RW-excl, 21.29 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 104451167527
Purge done for trx's n:o < 104392778218 undo n:o < 0 state: running but idle
History list length 28210362
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 281543977331744, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977275064, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977274192, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977273320, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977272448, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977271576, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977270704, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977269832, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977268960, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977268088, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977267216, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977266344, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977265472, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977264600, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977263728, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977261984, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977259368, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977260240, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 281543977256752, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 104451167518, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 17, OS thread handle 8496, query id 1289544002 System lock
---TRANSACTION 104451167516, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s)
MySQL thread id 19, OS thread handle 5800, query id 1289543998 System lock
---TRANSACTION 104451167514, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 22, OS thread handle 8580, query id 1289543994 System lock
---TRANSACTION 104451167483, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 1136, 0 row lock(s), undo log entries 9
MySQL thread id 20, OS thread handle 4184, query id 1289543966 System lock
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (read thread)
I/O thread 4 state: wait Windows aio (read thread)
I/O thread 5 state: wait Windows aio (read thread)
I/O thread 6 state: wait Windows aio (read thread)
I/O thread 7 state: wait Windows aio (read thread)
I/O thread 8 state: wait Windows aio (read thread)
I/O thread 9 state: wait Windows aio (read thread)
I/O thread 10 state: wait Windows aio (read thread)
I/O thread 11 state: wait Windows aio (read thread)
I/O thread 12 state: wait Windows aio (read thread)
I/O thread 13 state: wait Windows aio (read thread)
I/O thread 14 state: wait Windows aio (read thread)
I/O thread 15 state: wait Windows aio (read thread)
I/O thread 16 state: wait Windows aio (read thread)
I/O thread 17 state: wait Windows aio (read thread)
I/O thread 18 state: wait Windows aio (write thread)
I/O thread 19 state: wait Windows aio (write thread)
I/O thread 20 state: wait Windows aio (write thread)
I/O thread 21 state: wait Windows aio (write thread)
I/O thread 22 state: wait Windows aio (write thread)
I/O thread 23 state: wait Windows aio (write thread)
I/O thread 24 state: wait Windows aio (write thread)
I/O thread 25 state: wait Windows aio (write thread)
I/O thread 26 state: wait Windows aio (write thread)
I/O thread 27 state: wait Windows aio (write thread)
I/O thread 28 state: wait Windows aio (write thread)
I/O thread 29 state: wait Windows aio (write thread)
I/O thread 30 state: wait Windows aio (write thread)
I/O thread 31 state: wait Windows aio (write thread)
I/O thread 32 state: wait Windows aio (write thread)
I/O thread 33 state: wait Windows aio (write thread)
Pending normal aio reads: [0, 0, 0, 0, 0, 26, 12, 21, 11, 0, 0, 0, 0, 0, 0, 0] , aio writes: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] ,
 ibuf aio reads:, log i/o's:, sync i/o's:
Pending flushes (fsync) log: 0; buffer pool: 1
18294137846 OS file reads, 3939049769 OS file writes, 501366826 OS fsyncs
2591.48 reads/s, 16384 avg bytes/read, 1462.31 writes/s, 221.87 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 684, seg size 686, 137731849 merges
merged operations:
 insert 226078414, delete mark 11569229, delete 23374
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 4425293, node heap has 2670 buffer(s)
Hash table size 4425293, node heap has 631 buffer(s)
Hash table size 4425293, node heap has 1828 buffer(s)
Hash table size 4425293, node heap has 710 buffer(s)
Hash table size 4425293, node heap has 2220 buffer(s)
Hash table size 4425293, node heap has 678 buffer(s)
Hash table size 4425293, node heap has 1655 buffer(s)
Hash table size 4425293, node heap has 819 buffer(s)
4164.37 hash searches/s, 3072.66 non-hash searches/s
---
LOG
---
Log sequence number 49559127643621
Log flushed up to   49559127223192
Pages flushed up to 49558756238119
Last checkpoint at  49558755159387
0 pending log flushes, 0 pending chkp writes
2538073759 log i/o's done, 821.42 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 17574133760
Dictionary memory allocated 1741829010
Buffer pool size   1048576
Free buffers       7766
Database pages     1029599
Old database pages 380029
Modified db pages  106419
Pending reads      72
Pending writes: LRU 8, flush list 7, single page 0
Pages made young 6333764239, not young 352223515267
38.62 youngs/s, 103602.97 non-youngs/s
Pages read 18298095118, created 69291498, written 1327880400
2590.23 reads/s, 33.21 creates/s, 618.43 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 522 / 1000
Pages read ahead 2255.82/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1029599, unzip_LRU len: 0
I/O sum[401784]:cur[2928], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size   131072
Free buffers       938
Database pages     128747
Old database pages 47506
Modified db pages  12683
Pending reads      1
Pending writes: LRU 5, flush list 0, single page 0
Pages made young 873104312, not young 44184990504
5.50 youngs/s, 14192.16 non-youngs/s
Pages read 2334304911, created 10335300, written 170415102
354.44 reads/s, 4.25 creates/s, 93.08 writes/s
Buffer pool hit rate 988 / 1000, young-making rate 0 / 1000 not 501 / 1000
Pages read ahead 303.99/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128747, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size   131072
Free buffers       965
Database pages     128719
Old database pages 47535
Modified db pages  13648
Pending reads      31
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 777887910, not young 44203270232
5.04 youngs/s, 12995.08 non-youngs/s
Pages read 2267940300, created 8433895, written 165456825
304.15 reads/s, 5.33 creates/s, 81.70 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 573 / 1000
Pages read ahead 263.99/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128719, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 2
Buffer pool size   131072
Free buffers       964
Database pages     128714
Old database pages 47533
Modified db pages  12841
Pending reads      37
Pending writes: LRU 0, flush list 3, single page 0
Pages made young 787904906, not young 44115193930
5.25 youngs/s, 12589.81 non-youngs/s
Pages read 2276051646, created 8414061, written 165205211
312.28 reads/s, 3.75 creates/s, 76.46 writes/s
Buffer pool hit rate 988 / 1000, young-making rate 0 / 1000 not 522 / 1000
Pages read ahead 277.32/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128714, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 3
Buffer pool size   131072
Free buffers       1029
Database pages     128614
Old database pages 47457
Modified db pages  14484
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 779021485, not young 44109206384
4.62 youngs/s, 12606.22 non-youngs/s
Pages read 2276989031, created 8412120, written 165909504
317.53 reads/s, 2.58 creates/s, 74.96 writes/s
Buffer pool hit rate 988 / 1000, young-making rate 0 / 1000 not 496 / 1000
Pages read ahead 279.99/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128614, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 4
Buffer pool size   131072
Free buffers       1031
Database pages     128620
Old database pages 47463
Modified db pages  12079
Pending reads      2
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 775902888, not young 44059295729
4.62 youngs/s, 13492.15 non-youngs/s
Pages read 2291542407, created 8419618, written 164405853
336.44 reads/s, 4.58 creates/s, 75.33 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 541 / 1000
Pages read ahead 290.65/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128620, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 5
Buffer pool size   131072
Free buffers       988
Database pages     128683
Old database pages 47482
Modified db pages  13712
Pending reads      1
Pending writes: LRU 3, flush list 0, single page 0
Pages made young 775735918, not young 43732516344
3.54 youngs/s, 12124.20 non-youngs/s
Pages read 2285853523, created 8412213, written 164825751
318.49 reads/s, 1.92 creates/s, 73.41 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 500 / 1000
Pages read ahead 271.99/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128683, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 6
Buffer pool size   131072
Free buffers       1043
Database pages     128651
Old database pages 47470
Modified db pages  12656
Pending reads      0
Pending writes: LRU 0, flush list 4, single page 0
Pages made young 784502976, not young 43903888802
4.96 youngs/s, 12066.62 non-youngs/s
Pages read 2280628740, created 8417436, written 165422739
301.61 reads/s, 6.67 creates/s, 72.25 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 534 / 1000
Pages read ahead 263.99/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128651, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
---BUFFER POOL 7
Buffer pool size   131072
Free buffers       808
Database pages     128851
Old database pages 47583
Modified db pages  14316
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 779703844, not young 43915153342
5.08 youngs/s, 13536.73 non-youngs/s
Pages read 2284784560, created 8446855, written 166239415
345.28 reads/s, 4.12 creates/s, 71.25 writes/s
Buffer pool hit rate 987 / 1000, young-making rate 0 / 1000 not 517 / 1000
Pages read ahead 303.90/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 128851, unzip_LRU len: 0
I/O sum[50223]:cur[366], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
64 queries inside InnoDB, 0 queries in queue
64 read views open inside InnoDB
Process ID=6588, Main thread ID=7700, state: sleeping
Number of rows inserted 2494197218, updated 2635465834, deleted 12430993, read 421975421553
635.77 inserts/s, 868.38 updates/s, 2.54 deletes/s, 199101.12 reads/s
1 Like
6

Hi @CharlesR,
You can still use PMM on MySQL servers running on Windows. Go into PMM Inventory and add your MySQL server as a remote instance.

If you believe your situation is the same as that bug, I suggest opening a new bug on mysql’s site, reference the original bug and provide all the details of your situation including an example schema and all relevant my.cnf settings. Be sure to mention you are running on Windows.

There’s an extremely high probability that you’re seeing this issue because of Windows. Here’s something I found on the issue with many comments from other Windows users comparing performance to Linux windows - How to obtain good concurrent read performance from disk - Stack Overflow

1 Like
7

Hi @matthewb ,

I read the slack thread but I couldn’t find on windows where to change the Thread priority and scheduling for MySQL.

Do you know any tuning on windows that can be done to improve windows performance?

In linux it is possible to change several parameters of the operating system but I find almost nothing for Windows.

I opened the bug on mysql’s site but they are not considering it as a bug.

1 Like
8

Hi @CharlesR,
Unfortunately Windows is not a supported OS by Percona, so there isn’t much we can do to assist here. I would recommend reaching out to MySQL Community mailing lists, and other forums that might have more Windows users that can shed some information.

Obviously, our recommendation is to move your MySQL setup to a linux-based OS. You can easily set up a MySQL replica on a new linux server and perform a near-zero-downtime switchover.

1 Like
9

Thank you @matthewb !

But don’t you know of any tuning that can be done on Windows Server 2012 to improve this reading of ibds or in MySQL conf itself?

Switching to Linux would be ideal, but the issue is that my client is not familiar with Linux and uses everything in Windows environment.
I’m still not convinced that it doesn’t happen on Linux, I realized that my client is one of the few that uses a database with several schemas, but I’ll test it on linux to be sure.

The MySQL Community is not considering this as a problem, but a configuration error of mine, but I’ve already tested all possible configurations and I didn’t find anything to do Windows OS tuning for Database nor in the MySQL documentation itself.

1 Like
10

Hi Charles,
You mention that your server memory is 128G, but can you confirm how big is your buffer pool?

1 Like
11

Hi Michael,

innodb_buffer_pool_size = 100G

1 Like
12

I’m not a Windows expert, so sorry, I don’t know what can be tweaked within that OS to improve filesystem access.

This would be the only way to “prove” to the community that there is an issue. Have the same schema, same exact dataset on a Windows mysql and a linux mysql and time the startup times.

1 Like
13

So yours server need to read at least 309.442 files, perhaps only metadata. In this case seems very reasonable time for me. How long it takes to execute ls -alrt (or windows equivalent?) in such a directory?

Regards

1 Like
14

Hi @egel ,

dir /s
2022-10-20 01:33:27
2022-10-20 01:33:49
Total: 22 s

I believe that the time is not reasonable since in MySQL 5.5 and 5.6 the database started in 5 minutes at most.

Since I migrated to 5.7 I have had this problem for a long time, so I migrated to 8 and the problem remains.

1 Like
15

Yeah, seems mySQL doing little bit more then dir /s doing (it mentioned as well in the bug you quoted :“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.” ,
Btw. On my ssd disk of my laptop the time to ran dir /s over 130K files took much faster then 22 seconds.
Hovewer, indeed seems to be an BUG, why to do it single threaded as it done right now (according to the BUG you quoted)? is there any possibility for you to move to faster disks? spread databases/partitions over different disks? IMHO, It may help as workaround.
Regards

1 Like
16

I’m using a Hitachi 12k iOPS Storage, my client today doesn’t have the resources to improve this performance.
Even on local disks sdd mySQL on Windows takes this time to start, I’m going to test on a linux but I’ve seen a report that the same problem occurred.

And I believe that 12k iOPS is a satisfactory value.

I think mySQL doesn’t pay attention and doesn’t consider it a bug, only had two reports so far and they consider it fixed in 8 which is not true until then since I tested 8 and the delay continues to start mySQL.

1 Like
17

I have already performed these actions but nothing has been effective.

1 Like
18

I put together this little script to test on linux. It will create 400 databases, 100 tables inside each database, partitioned monthly (12). That should result in 40010012 = 480,000 files on disk.

#!/bin/bash

for j in `seq 1 400`; do
  ./my sql -e "CREATE DATABASE forum${j}"
  for i in `seq 1 100`; do
    ./my sql -e "CREATE TABLE forum${j}.logs${i} (
  id int unsigned NOT NULL AUTO_INCREMENT,
  entry varchar(50) DEFAULT NULL,
  created date NOT NULL,
  PRIMARY KEY (id,created)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
PARTITION BY LIST (month(created))
(PARTITION p1 VALUES IN (1) ENGINE = InnoDB,
 PARTITION p2 VALUES IN (2) ENGINE = InnoDB,
 PARTITION p3 VALUES IN (3) ENGINE = InnoDB,
 PARTITION p4 VALUES IN (4) ENGINE = InnoDB,
 PARTITION p5 VALUES IN (5) ENGINE = InnoDB,
 PARTITION p6 VALUES IN (6) ENGINE = InnoDB,
 PARTITION p7 VALUES IN (7) ENGINE = InnoDB,
 PARTITION p8 VALUES IN (8) ENGINE = InnoDB,
 PARTITION p9 VALUES IN (9) ENGINE = InnoDB,
 PARTITION p10 VALUES IN (10) ENGINE = InnoDB,
 PARTITION p11 VALUES IN (11) ENGINE = InnoDB,
 PARTITION p12 VALUES IN (12) ENGINE = InnoDB)"

echo "${j} - ${i}"
done
done
1 Like
19

I got through part of the script above on my home server (I ran out of space in /home and had to move the datadir somewhere else).

2022-10-20T19:59:33.719944Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-10-20T20:02:41.440370Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.

$ find /opt/media/data/ -name "*.ibd" | wc -l
123173

On my 4 drive RAID5 HDDs, XFS, Ubuntu 18, it took about 2 minutes to scan 123K innodb files. This was on MySQL Community 8.0.28.

1 Like
20

Thanks.

Did you land something in my.cnf ?

1 Like