Bug #83143 Performance regression in dictionary operations due to metadata locking
Submitted: 26 Sep 2016 2:52 Modified: 11 Dec 2017 15:21
Reporter: Szymon Komendera Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Data Dictionary Severity:S5 (Performance)
Version:8.0 OS:Any
Assigned to: CPU Architecture:Any

[26 Sep 2016 2:52] Szymon Komendera
Description:
MySQL 8.0 experiences performance degradation in certain scenarios that rely heavily on the metadata subsystem.

As an example, mysqldump sees 3.5x performance drop for schema-only dumps, all due to metadata locking during SHOW operations.

## Perf top on 5.7 while dumping

  42.15%  mysqld               [.] close_thread_tables(THD*)
   9.46%  mysqld               [.] my_qsort
   3.18%  mysqld               [.] TABLE::cleanup_gc_items()
   2.80%  [kernel]             [k] ext4_htree_store_dirent
   2.61%  [kernel]             [k] half_md4_transform
   2.47%  mysqld               [.] handler::ha_thd() const
   2.04%  mysqld               [.] MDL_context::find_ticket(MDL_request*, enum_mdl_duration*)
   1.64%  libc-2.19.so         [.] readdir64_r
   1.46%  mysqld               [.] ha_innobase::extra(ha_extra_function)
   1.44%  [kernel]             [k] str2hashbuf_signed
   1.32%  [kernel]             [k] __kmalloc
   1.28%  [kernel]             [k] kfree
   1.28%  libc-2.19.so         [.] 0x0000000000091db3
   0.88%  [kernel]             [k] rb_insert_color
   0.85%  [kernel]             [k] memcpy

## Perf top / stack on 8.0 while dumping

  59.42%  mysqld               [.] MDL_context::find_ticket(MDL_request*, enum_mdl_duration*)
  10.92%  mysqld               [.] close_thread_tables(THD*)
   9.23%  mysqld               [.] Release_acl_cache_locks::release(MDL_ticket*)
   2.83%  mysqld               [.] MDL_context::release_locks(MDL_release_locks_visitor*)
   0.97%  mysqld               [.] btr_search_guess_on_hash(dict_index_t*, btr_search_t*, dtuple_t const*, unsigned long, unsigned long, btr_cur_t*, unsigned long, mtr_t*)
   0.87%  mysqld               [.] TABLE::cleanup_gc_items()
   0.67%  mysqld               [.] handler::ha_thd() const
   0.56%  mysqld               [.] rec_init_offsets(unsigned char const*, dict_index_t const*, unsigned long*)
   0.51%  mysqld               [.] ha_innobase::extra(ha_extra_function)
   0.49%  mysqld               [.] MDL_ticket::get_key() const
   0.47%  mysqld               [.] row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)
   0.40%  libc-2.19.so         [.] 0x0000000000092123
   0.38%  libc-2.19.so         [.] 0x0000000000092111
   0.37%  mysqld               [.] row_sel_field_store_in_mysql_format_func(unsigned char*, mysql_row_templ_t const*, unsigned char const*, unsigned long)
   0.37%  libc-2.19.so         [.] 0x0000000000092117
   0.34%  libc-2.19.so         [.] 0x000000000009211d

#0  MDL_context::find_ticket (this=this@entry=0x7fcf68000be8, mdl_request=mdl_request@entry=0x7fcf54115c48,
    result_duration=result_duration@entry=0x7fd12c23bf4c) at /home/mysql/source/mysql-8.0/sql/mdl.cc:2805
#1  0x000000000101854f in MDL_context::try_acquire_lock_impl (this=this@entry=0x7fcf68000be8,
    mdl_request=mdl_request@entry=0x7fcf54115c48, out_ticket=out_ticket@entry=0x7fd12c23c008)
    at /home/mysql/source/mysql-8.0/sql/mdl.cc:3011
#2  0x000000000101942e in MDL_context::acquire_lock (this=this@entry=0x7fcf68000be8,
    mdl_request=mdl_request@entry=0x7fcf54115c48, lock_wait_timeout=<optimized out>)
    at /home/mysql/source/mysql-8.0/sql/mdl.cc:3596
#3  0x00000000008e58f1 in open_table_get_mdl_lock (mdl_ticket=<synthetic pointer>, flags=3, table_list=0x7fcf541158a8,
    ot_ctx=0x7fd12c23c400, thd=0x7fcf68000b50) at /home/mysql/source/mysql-8.0/sql/sql_base.cc:2801
#4  open_table (thd=thd@entry=0x7fcf68000b50, table_list=table_list@entry=0x7fcf541158a8, ot_ctx=ot_ctx@entry=0x7fd12c23c400)
    at /home/mysql/source/mysql-8.0/sql/sql_base.cc:3163
#5  0x00000000008ecfa6 in open_and_process_table (ot_ctx=0x7fd12c23c400, has_prelocking_list=false,
    prelocking_strategy=0x7fd12c23c490, flags=1, counter=0x7fd12c23c48c, tables=0x7fcf541158a8, lex=<optimized out>,
    thd=0x7fcf68000b50) at /home/mysql/source/mysql-8.0/sql/sql_base.cc:5226
#6  open_tables (thd=0x7fcf68000b50, start=start@entry=0x7fd12c23c498, counter=counter@entry=0x7fd12c23c48c,
    flags=flags@entry=1, prelocking_strategy=prelocking_strategy@entry=0x7fd12c23c490)
    at /home/mysql/source/mysql-8.0/sql/sql_base.cc:5855
#7  0x00000000010e0fc4 in open_tables (flags=1, counter=0x7fd12c23c48c, tables=0x7fd12c23c498, thd=<optimized out>)
    at /home/mysql/source/mysql-8.0/sql/sql_base.h:432
#8  dd::Open_dictionary_tables_ctx::open_tables (this=this@entry=0x7fd12c23c530)
    at /home/mysql/source/mysql-8.0/sql/dd/impl/transaction_impl.cc:100
#9  0x0000000000a534bf in dd::cache::Storage_adapter::get<dd::Item_name_key, dd::Abstract_table> (thd=thd@entry=0x7fcf68000b50,
    key=..., isolation=isolation@entry=ISO_READ_COMMITTED, object=object@entry=0x7fd12c23c608)
    at /home/mysql/source/mysql-8.0/sql/dd/impl/cache/storage_adapter.cc:100
#10 0x0000000000a501c5 in dd::cache::Shared_dictionary_cache::get_uncached<dd::Item_name_key, dd::Abstract_table> (
    this=<optimized out>, thd=thd@entry=0x7fcf68000b50, key=..., isolation=isolation@entry=ISO_READ_COMMITTED,
    object=object@entry=0x7fd12c23c608) at /home/mysql/source/mysql-8.0/sql/dd/impl/cache/shared_dictionary_cache.cc:103
#11 0x0000000000a25d18 in dd::cache::Dictionary_client::acquire_uncached<dd::View> (this=<optimized out>,
    schema_name="information_schema", object_name="TABLES", object=object@entry=0x7fcf63810380)
    at /home/mysql/source/mysql-8.0/sql/dd/impl/cache/dictionary_client.cc:1057
#12 0x0000000000bfaa5d in open_table_def (thd=thd@entry=0x7fcf68000b50, share=share@entry=0x7fcf63810040,
    open_view=open_view@entry=true, table_def=table_def@entry=0x0) at /home/mysql/source/mysql-8.0/sql/dd_table_share.cc:2260
#13 0x00000000008e44d2 in get_table_share (thd=thd@entry=0x7fcf68000b50, table_list=table_list@entry=0x7fcf628e6628,
    key=0x7fcf628e69ed "information_schema", key_length=key_length@entry=26, open_view=open_view@entry=true,
    hash_value=hash_value@entry=3834831062) at /home/mysql/source/mysql-8.0/sql/sql_base.cc:565
#14 0x00000000008e56e9 in get_table_share_with_discover (hash_value=3834831062, error=<synthetic pointer>, key_length=26,
    key=<optimized out>, table_list=0x7fcf628e6628, thd=0x7fcf68000b50) at /home/mysql/source/mysql-8.0/sql/sql_base.cc:685
#15 open_table (thd=thd@entry=0x7fcf68000b50, table_list=table_list@entry=0x7fcf628e6628, ot_ctx=ot_ctx@entry=0x7fd12c23e760)

How to repeat:
Attempt to create a schema-only dump from a database with a large number of tables. In my test, I created a server with 100 schemas and 10K tables each (1M tables total) and a attempted to dump one schema from it (10K tables, while the dictionary contains a total of 1M tables).

Tested on: AWS EC2 M4.4XL, 1TB @ 15K IOPS
Command: time mysqldump --no-data -uroot -pxxx s_1 > schema.sql

Dump time in 5.7.*: 10 min 45 sec
Dump time in 8.0: 36 min 5 sec

##

Note that performance drop is not observed in non-locking mode (--skip-lock-tables). This is because in default mode, mysqldump acquires a READ lock on all dumped tables, which forces MDL to follows a different (slower) code path.
[26 Sep 2016 11:51] MySQL Verification Team
Hello Szymon Komendera,

Thank you for the report.

Thanks,
Umesh
[26 Sep 2016 11:52] MySQL Verification Team
-- Schema 

CREATE DATABASE IF NOT EXISTS test;
use test;
DELIMITER //
 DROP PROCEDURE IF EXISTS ct//
 CREATE PROCEDURE ct()
 BEGIN
 	SET @v1  = 100;
	WHILE @v1 > 0 DO
		SET @s = CONCAT('DROP DATABASE IF EXISTS ', 's_' , @v1,'');
		PREPARE stm FROM @s;
		EXECUTE stm;
		
		SET @s = CONCAT('CREATE DATABASE ', 's_' , @v1,'');
		PREPARE stm FROM @s;
		EXECUTE stm;		
		SET @v2  = 10000;
		WHILE @v2 > 0 DO
			SET @s = CONCAT('CREATE TABLE ','s_',@v1,'.','t',@v2,'(id int not null)');
			PREPARE stm FROM @s;
			EXECUTE stm;
			SET @v2 = @v2 - 1;
		END WHILE;
		SET @v1 = @v1 - 1;
	END WHILE; 
 END //
DELIMITER ;
call ct; -- will create 100 Schema, and 10K tables in each schema

^^ recreate SP, and rerun call ct if you encounter any errors

-- Alternatively, you can use sysbench to create required schema
./bulk.sh

cat bulk.sh
#!/bin/bash

for i in {1..100}
do
    bin/mysql -uroot -S /tmp/mysql_ushastry.sock -e "CREATE DATABASE IF NOT EXISTS s_$i;"
    /home/umshastr/bugs/sysbench/bin/sysbench --test="/home/umshastr/bugs/sysbench/sysbench/tests/db/oltp.lua"  --num-threads=100 --mysql-table-engine=innodb --mysql-db="s_$i" --oltp-tables-count=10000 --oltp-table-size=1 --mysql-user=root --mysql-socket=/tmp/mysql_ushastry.sock  prepare
done

-- 5.7.15

rm -rf 83141
bin/mysqld --initialize-insecure --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15/83141 -v
bin/mysqld --basedir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15 --datadir=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15/83141 --core-file --socket=/tmp/mysql_ushastry.sock --port=3306 --log-error=/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15/83141/log.err 2>&1 &

mysql> call ct; -- will create 100 Schema, and 10K tables in each schema
Query OK, 0 rows affected (1 hour 1 min 2.16 sec)

[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15: time bin/mysqldump --no-data -uroot -S /tmp/mysql_ushastry.sock s_1 > schema.sql

real    9m11.213s
user    0m2.604s
sys     0m3.086s

[umshastr@hod03]/export/umesh/server/binaries/GABuilds/mysql-advanced-5.7.15: ls -lh schema.sql
-rw-r--r-- 1 umshastr common 3.2M Sep 26 11:14 schema.sql

-- 8.0

[umshastr@hod03]/export/umesh/server/binaries/Trunk/mysql-advanced-8.0: cat docs/INFO_SRC
commit: 47ba5514e4e485ef74579d6efed09bbbe58f8427
date: 2016-09-22 10:36:52 +0200
build-date: 2016-09-22 17:03:14 +0200
short: 47ba551
branch: mysql-trunk

MySQL source 8.0.1

rm -rf 83141
bin/mysqld  --initialize-insecure --basedir=/export/umesh/server/binaries/Trunk/mysql-advanced-8.0 --datadir=/export/umesh/server/binaries/Trunk/mysql-advanced-8.0/83141 -v
bin/mysqld --basedir=/export/umesh/server/binaries/Trunk/mysql-advanced-8.0 --datadir=/export/umesh/server/binaries/Trunk/mysql-advanced-8.0/83141 --core-file --socket=/tmp/mysql_ushastry.sock  --port=3306 --log-error=/export/umesh/server/binaries/Trunk/mysql-advanced-8.0/83141/log.err 2>&1 &

mysql> call ct; -- will create 100 Schema, and 10K tables in each schema
Query OK, 0 rows affected (1 hour 32 min 24.42 sec)

[umshastr@hod03]/export/umesh/server/binaries/Trunk/mysql-advanced-8.0: time bin/mysqldump --no-data -uroot -S /tmp/mysql_ushastry.sock s_1 > schema.sql

real    35m47.119s
user    0m2.561s
sys     0m3.230s
[11 Dec 2017 15:21] Daniel Price
Posted by developer:
 
Fixed as of the upcoming 8.0.4 release, and here's the changelog entry:

 Operations that rely heavily on the metadata locking (MDL) subsystem
caused a performance degradation. Traversal of MDL ticket lists was time
consuming in cases where there were large number of MDL tickets.