MySQL Bugs: #87827: Performance regression in "create table" speed and scalability in 8.0.3

Bug #87827	Performance regression in "create table" speed and scalability in 8.0.3
Submitted:	21 Sep 2017 14:09	Modified:	19 Jan 2018 20:28
Reporter:	Alexander Rubin	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	8.0.3	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
With the new tablespaces the speed of "create table" drops in 8.0.3 rc compared to 8.0.1

Non parallel run:
============

8.0.1

time ./install_on_mysql_8_0_single.sh

real    1m17.548s
user    0m0.796s
sys     0m1.628s

| Innodb_data_fsyncs                    | 10065

8.0.3

time ./install_on_mysql_8_0_single.sh

real    3m0.684s
user    0m0.956s
sys     0m1.792s

| Innodb_data_fsyncs                    | 30153

So it is doing 3x data_fsyncs in 8.0.3 (3 per each create table) as
opposed to MySQL 8.0.1 (1 per each create table). 

InnoDB config:

innodb_buffer_pool_size = 100G
innodb_io_capacity=20000
innodb_flush_log_at_trx_commit = 0
innodb_log_file_size = 2G
innodb_flush_method=O_DIRECT_NO_FSYNC
skip-log-bin

Script:

mysql test -e "CREATE TABLESPACE t ADD DATAFILE 't.ibd'
Engine=InnoDB;"
for i in {1..10000}
do
           mysql test -e "create table ab$i(i int) tablespace t"
done 

Parallel run:
=========

Here is the time to create 1M tables, running parallel in 100 threads
(64 CPU cores):

8.0.1:

real    25m28.536s
user    1m34.920s
sys     2m28.424s

(no mutex contention, ~3K IOPS)

8.0.3:

real    280m1.889s
user    1m51.072s
sys     2m51.728s

(huge mutex contention) 

Here is what I see in "show engine innodb status" when creating tables
in parallel in MySQL 8.0.3 rc.
I do not see it in 8.0.1

SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 605333
--Thread 139609863042816 has waited at dict0stats.cc line 2268 for
0.00 seconds the semaphore:
X-lock on RW-latch at 0x7ee38d02b858 created in file dict0dict.cc line
1101
a writer (thread id 139615228843776) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file
../../../mysql-8.0.3-rc/storage/innobase/handler/ha_innodb.cc line
13259
--Thread 139612545943296 has waited at dict0stats.cc line 2268 for
0.00 seconds the semaphore:
X-lock on RW-latch at 0x7ee38d02b858 created in file dict0dict.cc line
1101
a writer (thread id 139615228843776) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file
../../../mysql-8.0.3-rc/storage/innobase/handler/ha_innodb.cc line
13259
--Thread 139615232042752 has waited at ha_innodb.cc line 13259 for
0.00 seconds the semaphore:
X-lock on RW-latch at 0x7ee38d02b858 created in file dict0dict.cc line
1101
a writer (thread id 139615228843776) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file not yet reserved line 0
Last time write locked in file
../../../mysql-8.0.3-rc/storage/innobase/handler/ha_innodb.cc line
13259
--Thread 139625831917312 has waited at dict0stats.cc line 2268 for
0.00 seconds the semaphore:
X-lock on RW-latch at 0x7ee38d02b858 created in file dict0dict.cc line
1101 

How to repeat:
Create tables script (non parallel)

mysql test -e "CREATE TABLESPACE t ADD DATAFILE 't.ibd'
Engine=InnoDB;"
for i in {1..10000}
do
           mysql test -e "create table ab$i(i int) tablespace t"
done 

Create tables script (parallel, 10K databases, 1M tables)

function do_db {
        mysql -vvv -e "create database $db";
        mysql -vvv $db -e "CREATE TABLESPACE $db ADD DATAFILE '$db.ibd' Engine=InnoDB;"
        for i in {1..100}
        do
                table="CREATE TABLE sbtest$i ( id int(10) unsigned NOT NULL AUTO_INCREMENT, k int(10) unsigned NOT NULL DEFAULT '0', c varchar(120) NOT NULL DEFAULT '', pad varchar(60) NOT NULL DEFAULT '', PRIMARY KEY (id), KEY k_1 (k) ) ENGINE=InnoDB DEFAULT CHARSET=latin1 tablespace $db;"
                mysql $db -e "$table"
        done
}

c=0
for m in {1..100} 
do
        for i in {1..100} 
        do
                let c=$c+1
                echo $c 
                db="test_sbtest_$c"
                do_db &
        done
        wait
done

Hello Alexander,

Thank you for the report and test case.
With the provided test case I'm observing a noticeable drop in 8.0.3 but not that much high which you had noticed. I'm joining activity log shortly.

Regards,
Umesh

Test results - 8.0.0, 8.0.1, 8.0.2,8.0.3

Attachment: 87827_8_0_1_2_3.results (application/octet-stream, text), 105.27 KiB.

Can it be related to this:

"InnoDB: Serialized Dictionary Information (SDI) is now present in all InnoDB tablespace files except for temporary tablespace and undo tablespace files. SDI is serialized metadata for schema, table, and tablespace objects. The presence of SDI data provides metadata redundancy. For example, dictionary object metadata may be extracted from tablespace files if the data dictionary becomes unavailable. SDI extraction is performed using the ibd2sdi tool. SDI data is stored in JSON format.

The inclusion of SDI data in tablespace files increases tablespace file size. An SDI record requires a single index page, which is 16k in size by default. However, SDI data is compressed when it is stored to reduce the storage footprint."
https://dev.mysql.com/doc/relnotes/mysql/8.0/en/news-8-0-3.html#mysqld-8-0-3-data-dictiona...

Alex's related article, see https://www.percona.com/blog/2017/10/01/one-million-tables-mysql-8-0/

Running "Show engine innodb status" shows the most frequent one is:

| InnoDB | rwlock: dict0dict.cc:1101  | waits=1296771 |

Posted by developer:
 
From my previous testing, this should be due to new DDL log written under the dict mutex and lock, which makes the dict_operation_lock too hot.

I'm having a patch to remove the dict_operation_lock for CREATE TABLE at hand. The performance result looks promising, I will test it a bit more.

Posted by developer:
 
Fixed as of the upcoming 8.0.5, 9.0.0 release, and here's the changelog entry:

Locks related to data dictionary operations caused a degradation in
CREATE TABLE performance.