| 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: | |
| Category: | MySQL Server: Data Dictionary | Severity: | S5 (Performance) |
| Version: | 8.0 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[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.
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.