Bug #103195 | it gets very slow to access an empty table after drop a big database | ||
---|---|---|---|
Submitted: | 2 Apr 2021 9:48 | Modified: | 12 Apr 2021 14:42 |
Reporter: | Brian Yue (OCA) | Email Updates: | |
Status: | Verified | Impact on me: | |
Category: | MySQL Server: Data Dictionary | Severity: | S5 (Performance) |
Version: | 8.0 | OS: | Linux (rhel-7.4) |
Assigned to: | CPU Architecture: | Any (x86-64) |
[2 Apr 2021 9:48]
Brian Yue
[2 Apr 2021 12:33]
MySQL Verification Team
Hi Mr. Yue, Thank you for your bug report. However, this does not seem to be a bug. We have optimised our server properly and then, we could not repeat the behaviour that you report. Both MySQL and OS need to be configured properly, especially the variable that define the sizes of the caches for schemas and tables. Hence, please try our suggestions and then let us know if you have improved the behaviour.
[6 Apr 2021 1:16]
Brian Yue
Hello, I have tried your suggestion and modified some configurations of both OS and mysql server. Then I tried to repeat this problem, and succeed to repeat it. Different with last report, I create 100,000 tables in the database, which is more than last time (30,000 tables). By the way, the slow-accessed tables should not be accessed (except for creation) before `drop database`, because new-accessed tables are slow to access after `drop database`. And, I believe that this is a bug, and I guess I have found where it locates :) [yxxdb_8022@localhost ~]$ mysql -uroot -S bin/mysql1.sock Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 61 Server version: 8.0.22 Source distribution Copyright (c) 2000, 2020, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> mysql> mysql> mysql> show variables like '%cache%'; +---------------------------------+----------------------+ | Variable_name | Value | +---------------------------------+----------------------+ ......... | schema_definition_cache | 100000 | | stored_program_cache | 256 | | stored_program_definition_cache | 256 | | table_definition_cache | 520000 | | table_open_cache | 520000 | | table_open_cache_instances | 16 | | tablespace_definition_cache | 520000 | | thread_cache_size | 100 | +---------------------------------+----------------------+ 21 rows in set (0.01 sec) mysql> mysql> system ulimit -a core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 1030529 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 655360 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 655360 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited mysql> mysql> mysql> drop database if exists yxx; create database yxx; use yxx; create table t1(id int); create table t2(id int); Query OK, 0 rows affected, 1 warning (0.00 sec) create table t3(id int); create table t4(id int); mysql> create database yxx; create table t5(id int); create table t6(id int); create table t7(id int); create table t8(id int); create table t9(id int); create table t10(id int); Query OK, 1 row affected (0.01 sec) mysql> use yxx; drop database if exists mytest; create database mytest; use mytest;Database changed mysql> mysql> create table t1(id int); Query OK, 0 rows affected (0.01 sec) mysql> create table t2(id int); Query OK, 0 rows affected (0.00 sec) mysql> create table t3(id int); Query OK, 0 rows affected (0.01 sec) mysql> create table t4(id int); Query OK, 0 rows affected (0.02 sec) mysql> create table t5(id int); Query OK, 0 rows affected (0.01 sec) mysql> create table t6(id int); Query OK, 0 rows affected (0.00 sec) mysql> create table t7(id int); Query OK, 0 rows affected (0.01 sec) mysql> create table t8(id int); Query OK, 0 rows affected (0.00 sec) mysql> create table t9(id int); Query OK, 0 rows affected (0.01 sec) mysql> create table t10(id int); Query OK, 0 rows affected (0.01 sec) mysql> mysql> drop database if exists mytest; Query OK, 0 rows affected, 1 warning (0.00 sec) mysql> create database mytest; Query OK, 1 row affected (0.00 sec) use mytest; mysql> CREATE TABLE `t_1`( -> EVTBKNO char(3) NOT NULL COMMENT '银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号银行号', /* !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! */ /* It's too long to place all fields, please reference to the first reported information to find how to create table t_1 */ /* !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! */ -> , GDB_BID INT NOT NULL DEFAULT -1, INDEX(`GDB_BID`), GTID BIGINT UNSIGNED NOT NULL DEFAULT 0) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin; Query OK, 0 rows affected, 10 warnings (0.16 sec) mysql> mysql> delimiter / mysql> create procedure proc1() -> BEGIN -> DECLARE i INT; -> DECLARE sql_text VARCHAR(2000); -> -> SET i=2; -> SET sql_text=''; -> -> WHILE i<100000 DO -> SET sql_text=CONCAT('CREATE TABLE t_', i); -> SET sql_text=CONCAT(sql_text, ' like t_1;'); -> SET @sql_text = sql_text; -> PREPARE stmt FROM @sql_text; -> EXECUTE stmt; -> DEALLOCATE PREPARE stmt; -> -> SET i=i+1; -> END WHILE; -> END / Query OK, 0 rows affected (0.00 sec) mysql> DELIMITER ; mysql> mysql> call proc1(); mysql> drop database mytest; Query OK, 99999 rows affected (2 hours 24 min 47.14 sec) mysql> mysql> select * from yxx.t1; Empty set (2.09 sec) mysql> select * from yxx.t2; Empty set (0.33 sec) mysql> select * from yxx.t3; Empty set (0.31 sec) mysql> select * from yxx.t4; Empty set (0.17 sec) mysql> select * from yxx.t5; Empty set (0.21 sec) mysql> mysql> mysql> mysql> set @@session.long_query_time = 0; Query OK, 0 rows affected (0.00 sec) mysql> select * from yxx.t6; Empty set (0.23 sec) mysql> select * from yxx.t7; Empty set (0.34 sec) mysql> select * from yxx.t8; Empty set (0.13 sec) mysql> select * from yxx.t9; Empty set (0.39 sec)
[6 Apr 2021 12:46]
MySQL Verification Team
Hi Mr. Yue, Thank you for your feedback. Can you clear out the crucial part of what you wrote: " the slow-accessed tables should not be accessed (except for creation) before `drop database`, because new-accessed tables are slow to access after `drop database`. " What do you mean by "slow-accessed" tables ??? How would you recommend that it is accessed if someone runs a query on such a table ??? I guess that you know that there are MANY operations to be performed when schema is dropped. Each table should be removed from all caches, data dictionaries etc. All files belonging to the table / tablespaces, have to be accessed and removed by OS, not by MySQL. Next, how can you access "slow-accessed" tables, after its schema is dropped ??? Last , but not least, the bottleneck for each of the operation, like open, close, unlink etc, is not in our server, but in OS !!!!! Hence, we still do not understand how do you see this as a bug in our server !!!!
[6 Apr 2021 13:55]
Brian Yue
Hello, I'm sorry that I didn't express myself well. I my testcase, I create 2 schemas (`yxx` and `mytest`). Schema `mytest` is created and filled with many many tables (30000 or 100000), and schema `mytest` is later dropped. After dropping schema `mytest`, I suppose that mysql server will get slow in some step, and in order to prove this I create another schema (`yxx`) and tables for testing response time of mysql-server after dropping schema `mytest`. So my steps are: (a) Make some preparations: create schema `yxx` and fill it with some tables (t1, t2, ... , t9), which will be accessed after dropping schema `mytest`. And, these tables are not filled with any records. I used `slow-accessed tables` to represent them, because they will be accessed after dropping `mytest`, and in my test this process is slow. (b) Create schema `mytest` and fill it with 30000 empty tables, and then drop `mytest`. (c) After `drop database mytest` command gives me a successful response, now we can check the response time of mysql-server. So, we can use tables of schema `yxx` to do this test, like `select * from yxx.t1`, `select * from yxx.t2`, .... At this time, I find that the select commands in step (c) behaves slowly. Commonly these select commands should be finished very fast, like 0.02 sec, but actually select commands behave very slow (`select * from yxx.t9` costs 0.39 sec). And, this is not temporary, this can happen after 1min, 30min, 1 hour, 12 hours .... In my last test, I dropped `mytest` in the evening, and it's also slow to do select commands in the morning of the second day (I'll paste the slow log later). I notice that you mention there are many operations in `drop` command, I think it's not related with this problem, because it's slow to do `select` command on tables of the other schema (`yxx`), not the dropped schema (`mytest`). Also, you memtion `bottleneck for each of the operation`. In my testcase, select commands on tables of schema `yxx` behave slow after dropping `mytest`, but are fast before executing `drop database mytest`, and keep slow until restarting mysql-server. I have reproduced this problem for many times (about 6 times), and it's easy for me to do this. And, the reason for why I said this is a bug is that, I have found where the problem is, and I have fixed this problem. After my fix, my server executes `select * from yxx.t1/t2/...` very fast after dropping `mytest` (also about 0.01 sec).
[6 Apr 2021 14:03]
Brian Yue
[slow log]: [yxxdb_8022@localhost data]$ cat localhost-slow.log /home/yxxdb_8022/bin/mysqld, Version: 8.0.22 (Source distribution). started with: Tcp port: 6314 Unix socket: /home/yxxdb_8022/bin/mysql1.sock Time Id Command Argument # Time: 2021-04-05T23:44:03.738061+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 2077.401685 Lock_time: 0.000086 Rows_sent: 0 Rows_examined: 0 use mytest; SET timestamp=1617637443; call proc1(); # Time: 2021-04-06T02:08:50.885122+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 8687.146617 Lock_time: 0.032888 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617637443; drop database mytest; # Time: 2021-04-06T02:08:54.014180+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.000115 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617646134; set @@session.long_query_time = 0; # Time: 2021-04-06T02:08:54.245801+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.231493 Lock_time: 0.014765 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617646134; select * from yxx.t6; # Time: 2021-04-06T02:08:54.585144+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.339013 Lock_time: 0.013929 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617646134; select * from yxx.t7; # Time: 2021-04-06T02:08:54.709728+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.124227 Lock_time: 0.010292 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617646134; select * from yxx.t8; # Time: 2021-04-06T02:08:55.100856+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.390798 Lock_time: 0.011380 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617646134; select * from yxx.t9; # Time: 2021-04-06T08:50:51.098775+08:00 # User@Host: root[root] @ localhost [] Id: 61 # Query_time: 0.369424 Lock_time: 0.036231 Rows_sent: 0 Rows_examined: 0 SET timestamp=1617670250; select * from yxx.t10; [yxxdb_8022@localhost data]$
[7 Apr 2021 12:30]
MySQL Verification Team
Hi Mr. Yue, We do understand what you are reporting. However, this is not a bug. Simply, for those number of tables, these phenomena are expected to occur. Both on the OS side and on MySQL side. It takes time to clear filesystem cache, change open tables vector in OS, manipulate all table caches in MySQL server. In short, these phenomena are expected behaviour with a number of tables that you are using. Not a bug.
[7 Apr 2021 13:09]
Brian Yue
Hello, I'm so disappointed that you think this is not a bug. I definitely and absolutely disagree with you !!! I have questions: (1) You said `It takes time to clear filesystem cache, change open tables vector in OS, manipulate all table caches in MySQL server`, but have you noticed that, mysql-server behaves always slowly for `select * from yxx.t1/t2/..`, event after 6 hours it still keeps slow. Do you think the operations you memtioned can take so much time? I'm sure that, event after 1 day, 2 days, ..., 30 days, it will always keep slow !!!! (2) You mean that it's the operations you memtioned that makes mysql-server behaves slow. Now that you give this conclusion, have you ever do some tests? have you ever watch the cost time of system calls? have you ever modify code of mysql-server to print some logs to check which function costs so much time? have you ever thought what if this is really a bug ? (3) I have modified code of my server and built a new server, and the problem is no more existed in my new server, but I have never modified code about what you mentioned. So, why is the problem not existed in my new server? I think you should take it seriously about this problem.
[7 Apr 2021 13:20]
MySQL Verification Team
Hi Mr. Yue, First of all, this is a very well known behaviour to us. Yes, we have done lots of testing, profiling and measurements of these phenomena. We had to , since we were actively been developing MySQL server, starting from 1997 until 2009, after which we have been only involved in fixing some bugs and performance bottlenecks. Also, slow query time of 0 will print you all queries in the slow query log. Not a bug.
[7 Apr 2021 13:34]
Brian Yue
Hello, I know that you are professional on MySQL, but I don't think you knows everything about it. For analyzing and fixing this bug, I cost 5 days to modify code, print log, do many stastics. And as a result, I fixed this bug. This problem is not existed anymore in my server. You said this is well known, but have you thought that maybe this is always a bug (or a performance problem), but never realized. And why can I fix this problem ? I'd like to share my solution code, but under the premise you accept this as a bug.
[8 Apr 2021 6:21]
Brian Yue
Hello, Today I tried my test on MySQL8.0.22 version, and found that it needs a different way to reproduce the problem I raised. Different with the steps I previouslt told you, 2 sessions of mysql client are used, one is used to execute `drop database mytest` command, and the other is used to execute `select * from yxx.t1/t2/....` to check response time of mysql-server. Comparison between the original version of MySQL8.0.22 and the modified version of MySQL8.0.22 (by me): ============= THE ORIGINAL VERSION OF MYSQL8.0.22 ============== [session 1] mysql> drop database mytest; ^[[1;5F^[[1;5FQuery OK, 29999 rows affected (17 min 53.94 sec) [session 2] mysql> select * from yxx.t1; Empty set (0.23 sec) mysql> select * from yxx.t2; Empty set (0.03 sec) mysql> select * from yxx.t3; Empty set (0.02 sec) mysql> select * from yxx.t4; Empty set (0.01 sec) mysql> select * from yxx.t5; Empty set (0.01 sec) mysql> select * from yxx.t6; Empty set (0.02 sec) mysql> select * from yxx.t7; Empty set (0.03 sec) mysql> select * from yxx.t8\; ERROR: Unknown command '\;'. -> ^C mysql> select * from yxx.t9; Empty set (0.04 sec) mysql> select * from yxx.t10; Empty set (0.02 sec) mysql> select * from yxx.t11; Empty set (0.05 sec) mysql> select * from yxx.t12; Empty set (0.03 sec) mysql> select * from yxx.t13; Empty set (0.02 sec) mysql> select * from yxx.t14; Empty set (0.01 sec) mysql> select * from yxx.t15; Empty set (0.01 sec) mysql> select * from yxx.t16; Empty set (0.03 sec) mysql> select * from yxx.t17; Empty set (0.06 sec) mysql> select * from yxx.t18; Empty set (0.05 sec) ============= THE MODIFIED VERSION OF MYSQL8.0.22 BY ME ============== [session 1] mysql> drop database mytest; Query OK, 29999 rows affected (10 min 23.65 sec) [session 2] mysql> mysql> select * from yxx.t1; Empty set (0.01 sec) mysql> select * from yxx.t2; Empty set (0.00 sec) mysql> select * from yxx.t3; Empty set (0.00 sec) mysql> select * from yxx.t4; Empty set (0.00 sec) mysql> select * from yxx.t5; Empty set (0.00 sec) It's not too obvious comparing to the cost time I previously told you, select commands cost time mostly from 0.03 sec to 0.23 sec (not stable, sometimes costs long time), while on the modified version by me, select commands mostly cost time <= 0.01 sec (very stable, <= 0.01 sec). So I think it's a big gap. Secondly, let's check the time of drop database. `drop database mytest` command cost time about 17 min 54 sec, while after modified the same command costs about 10 min 24 sec, which means my server behaves faster for `drop database` command. And, all the 2 benefits comes from my fix of the bug I mentioned.
[9 Apr 2021 12:54]
MySQL Verification Team
Hi Mr. Yue, Well, we have done something better. We have verified your report as a performance improvement feature. Now, you can share your solution with us. We wait on your patch.
[12 Apr 2021 14:42]
Brian Yue
Hello, Thanks for your verification, which I think is a pretty smart choice :) Patch like this (later I'll upload it as a file to `Contributions` part), it will bring a big improvement of performance for `drop database` and `create many tables`. diff --git a/sql/mdl.cc b/sql/mdl.cc index 2413b69..ab901e3 100644 --- a/sql/mdl.cc +++ b/sql/mdl.cc @@ -182,8 +182,28 @@ class MDL_map { */ int32 unused_locks = ++m_unused_lock_objects; - while (unused_locks > mdl_locks_unused_locks_low_water && - (unused_locks > m_locks.count * MDL_LOCKS_UNUSED_LOCKS_MIN_RATIO)) { + /* + #BUG-103195: previously we didn't consider dummy nodes while releasing + unused locks. If there are too many dummy nodes and too little unused + locks, it become pretty difficult to find enough unused lock objects. + As I tested, after creating and droping a database with 30000 tables, + number of buckets will be increase to about 4 million, and there are few + MDL_lock objects after droping database, so when we have to release a + unused lock, we have to traverse too many dummy nodes, which exausts + a lot of time (I noticed it costs 38ms to find a unused lock once). It + is better to consider count of buckets (each bucket has a dummy node + after initialized) while making a decision to unused locks or not, and + we use count of buckets to represent count of dummy nodes approximately. + Avoiding too many unused locks, we mark a upper-limit of memory, exceeded + locks will be released anyway. + */ + while ((unused_locks > mdl_locks_unused_locks_low_water && + (unused_locks > (m_locks.count + m_locks.size) * MDL_LOCKS_UNUSED_LOCKS_MIN_RATIO)) + || + (m_locks.element_size > 0 && + (MDL_LOCKS_UNUSED_LOCKS_MAX_MEMORY / m_locks.element_size < (uint)unused_locks)) ) { /* If number of unused lock objects exceeds low water threshold and unused/total objects ratio is high enough - try to do random dive diff --git a/sql/mdl.h b/sql/mdl.h index ebcbe09..f881a0d 100644 --- a/sql/mdl.h +++ b/sql/mdl.h @@ -1702,21 +1702,30 @@ extern ulong max_write_lock_count; extern int32 mdl_locks_unused_locks_low_water; /** Default value for threshold for number of unused MDL_lock objects after exceeding which we start considering freeing them. Only unit tests use different threshold value. */ -const int32 MDL_LOCKS_UNUSED_LOCKS_LOW_WATER_DEFAULT = 1000; +const int32 MDL_LOCKS_UNUSED_LOCKS_LOW_WATER_DEFAULT = 10000; /** - Ratio of unused/total MDL_lock objects after exceeding which we - start trying to free unused MDL_lock objects (assuming that + Ratio of unused/(total MDL_lock objects + count of buckets) after exceeding + which we start trying to free unused MDL_lock objects (assuming that mdl_locks_unused_locks_low_water threshold is passed as well). Note that this value should be high enough for our algorithm using random dives into hash to work well. */ -const double MDL_LOCKS_UNUSED_LOCKS_MIN_RATIO = 0.25; +const double MDL_LOCKS_UNUSED_LOCKS_MIN_RATIO = 0.125; + +/** + Max memory usage of unused MDL_lock objects, now default 100MB. + If memory of unused locks exceeds this number, force-release will happen. +*/ +const int32 MDL_LOCKS_UNUSED_LOCKS_MAX_MEMORY = 100*1024*1024; + int32 mdl_get_unused_locks_count();
[12 Apr 2021 14:45]
Brian Yue
solution code, about lf_hash (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.
Contribution: patch_103195.txt (text/plain), 3.15 KiB.
[13 Apr 2021 12:17]
MySQL Verification Team
Hi Mr. Yue, Thank you for your contribution.