| Bug #98750 | SHOW FIELDS command regression on MySQL 8.0 | ||
|---|---|---|---|
| Submitted: | 26 Feb 2020 20:11 | Modified: | 20 May 2020 17:40 |
| Reporter: | Juan Arruti | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: Information schema | Severity: | S5 (Performance) |
| Version: | 8.0, 8.0.19 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | regression | ||
[27 Feb 2020 8:46]
Przemyslaw Malkowski
As similar report was rejected due to presenting results with I_S profiling - https://bugs.mysql.com/bug.php?id=92195, let me show quick Performance Schema stats for these below: On 8.0.19: mysql [localhost:8020] {msandbox} (performance_schema) > SELECT EVENT_ID, SQL_TEXT FROM events_statements_history_long WHERE EVENT_NAME = 'statement/sql/show_fields'; +----------+-------------------------------+ | EVENT_ID | SQL_TEXT | +----------+-------------------------------+ | 781 | show full fields from db1.t1 | | 1018 | SHOW FIELDS FROM test.t1 | | 1102 | SHOW FULL FIELDS FROM test.t1 | +----------+-------------------------------+ 3 rows in set (0.00 sec) mysql [localhost:8020] {msandbox} (performance_schema) > SELECT EVENT_NAME, SOURCE, (TIMER_END-TIMER_START)/1000000000 as 'DURATION (ms)' FROM events_stages_history_long WHERE NESTING_EVENT_ID=1018; +--------------------------------------+----------------------------------+---------------+ | EVENT_NAME | SOURCE | DURATION (ms) | +--------------------------------------+----------------------------------+---------------+ | stage/sql/starting | init_net_server_extension.cc:101 | 0.6730 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0078 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0054 | | stage/sql/Opening tables | sql_base.cc:5591 | 0.3097 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0038 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0029 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0030 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0031 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0031 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0044 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0586 | | stage/sql/init | sql_select.cc:171 | 0.1348 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0038 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0027 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0027 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0028 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0030 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0311 | | stage/sql/System lock | lock.cc:331 | 0.0101 | | stage/sql/optimizing | sql_optimizer.cc:282 | 0.0259 | | stage/sql/statistics | sql_optimizer.cc:502 | 0.1066 | | stage/sql/preparing | sql_optimizer.cc:583 | 0.0358 | | stage/sql/Creating tmp table | sql_executor.cc:348 | 0.0621 | | stage/sql/executing | sql_union.cc:1409 | 0.0826 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0208 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0115 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0112 | | stage/sql/checking permissions | sql_authorization.cc:2176 | 0.0657 | | stage/sql/end | sql_select.cc:222 | 0.0045 | | stage/sql/query end | sql_parse.cc:4606 | 0.0039 | | stage/sql/waiting for handler commit | handler.cc:1589 | 0.0114 | | stage/sql/removing tmp table | sql_tmp_table.cc:2311 | 0.0078 | | stage/sql/closing tables | sql_parse.cc:4657 | 0.0122 | | stage/sql/freeing items | sql_parse.cc:5330 | 0.0364 | | stage/sql/cleaning up | sql_parse.cc:2184 | 0.0007 | +--------------------------------------+----------------------------------+---------------+ 35 rows in set (0.00 sec) mysql [localhost:8020] {msandbox} (performance_schema) > SELECT EVENT_NAME,count(*) FROM events_stages_history_long WHERE NESTING_EVENT_ID=1018 GROUP BY EVENT_NAME; +--------------------------------------+----------+ | EVENT_NAME | count(*) | +--------------------------------------+----------+ | stage/sql/starting | 1 | | stage/sql/checking permissions | 19 | | stage/sql/Opening tables | 1 | | stage/sql/init | 1 | | stage/sql/System lock | 1 | | stage/sql/optimizing | 1 | | stage/sql/statistics | 1 | | stage/sql/preparing | 1 | | stage/sql/Creating tmp table | 1 | | stage/sql/executing | 1 | | stage/sql/end | 1 | | stage/sql/query end | 1 | | stage/sql/waiting for handler commit | 1 | | stage/sql/removing tmp table | 1 | | stage/sql/closing tables | 1 | | stage/sql/freeing items | 1 | | stage/sql/cleaning up | 1 | +--------------------------------------+----------+ 17 rows in set (0.00 sec) On 5.7.29: mysql [localhost:5734] {msandbox} (performance_schema) > SELECT EVENT_ID, SQL_TEXT FROM events_statements_history_long WHERE EVENT_NAME = 'statement/sql/show_fields'; +----------+--------------------------+ | EVENT_ID | SQL_TEXT | +----------+--------------------------+ | 13 | SHOW FIELDS FROM test.t1 | | 675 | SHOW FIELDS FROM test.t1 | | 736 | SHOW FIELDS FROM test.t1 | +----------+--------------------------+ 3 rows in set (0.00 sec) mysql [localhost:5734] {msandbox} (performance_schema) > SELECT EVENT_NAME,count(*) FROM events_stages_history_long WHERE NESTING_EVENT_ID=736 GROUP BY EVENT_NAME; +--------------------------------+----------+ | EVENT_NAME | count(*) | +--------------------------------+----------+ | stage/sql/checking permissions | 3 | | stage/sql/cleaning up | 1 | | stage/sql/closing tables | 1 | | stage/sql/end | 1 | | stage/sql/executing | 1 | | stage/sql/freeing items | 1 | | stage/sql/init | 1 | | stage/sql/Opening tables | 2 | | stage/sql/optimizing | 1 | | stage/sql/preparing | 1 | | stage/sql/query end | 1 | | stage/sql/removing tmp table | 1 | | stage/sql/Sending data | 1 | | stage/sql/starting | 1 | | stage/sql/statistics | 1 | | stage/sql/System lock | 1 | +--------------------------------+----------+ 16 rows in set (0.00 sec) So, for the same query, 5.7 does checking permissions stage 3 times versus 8.0 does it 19 times. For application frameworks relying on SHOW FIELDS and doing those in high concurrency, that results in a real performance regression after upgrading from 5.7 to 8.0.
[27 Feb 2020 8:57]
MySQL Verification Team
Hello Juan Arruti, Thank you for the report and test case. Verified as described. regards, Umesh
[22 Mar 2020 13:25]
Tom Sommer
This also affects "SHOW FULL COLUMNS", "SHOW TABLES" etc.
[3 Apr 2020 5:09]
kuntal basu
IS anybody working on this fix?
[12 May 2020 17:34]
Trey Raymond
I have a hard time blaming mysql for this one (and I love to blame mysql!), SHOW has always been a very expensive operation in all its forms, only intended to be run on rare occasion - nothing in that code has ever been designed to run concurrently. It's true that these are more expensive in 8 than earlier, but that seems to be a side effect of the data dictionary changes. If you look at the actual sql executed to solve something like SHOW FIELDS, it's not a cheap query (you can see it from statement digests). Still, it seems to be working as intended, just not how some folks want it to work. "Fast SHOW" is really a feature request, since it has never been a part of mysql, just a little more visible now. Still, seems like a lot of people want it, and any useful new feature is much appreciated. So despite being classed as such, devs may still want to put some time into it shorter term. I remember yowling for features in MSR when 5.7 came out and getting them. One tip, info schema is smarter than most people think, and won't resolve data that isn't needed for a query. So if you just need, say, column names, and not the rest, you can run "select column_name from information_schema.columns where table_schema=database() and table_name='x';" and it will return much faster than "show columns" - it's still a metadata lookup, not cheap, but a drop-in for any of you affected by this which will improve things. The same works for i_s.tables vs show tables.
[15 May 2020 9:52]
Tom Sommer
We can agree using SHOW FIELDS etc. not suboptimal, but sadly WordPress uses this extensively and that basically means MySQL 8 and WordPress does not play well together at this time. Regardless of usage, the extra permission checks are surely a regression?
[20 May 2020 17:40]
Paul DuBois
Posted by developer: Fixed in 8.0.21. Excessive access checks were performed on certain of the data dictionary tables that underlie INFORMATION_SCHEMA views, resulting in slow SHOW COLUMNS performance. These checks were reduced to improve performance.
[21 May 2020 11:30]
Satya Bodapati
My observation is that although the number of check permissions on DD tables is higher in 8.0, they are not the main contributors of regression. I_S queries in 5.7, can directly use the cached object of the table (TABLE*) and answer the query SHOW FIELDS. Whereas in 8.0, it is a view, so there is much more overhead in doing btree(index) scan, joining tables, finding columns etc. Nothing can beat the cache access. May be 8.0 too can check if the table is in cache first and then answer the SHOW FIELDS query directly. (Although this will be limited to queries than answer by looking at TABLE* and TABLE_SHARE*)
[21 May 2020 11:32]
Satya Bodapati
correction: ((Although this will be limited to queries *that* answer by looking at TABLE* and TABLE_SHARE*)
[21 May 2020 12:09]
Tom Sommer
Sounds plausible. Perhaps open new issue on this?
Description: There is a performance regression when running SHOW FIELDS command, which is really noticeable under high concurrency. Profile output shows there are several "checking permissions" more events than in 5.7, which is the state I'm seeing when running show processlist: # MySQL 8.0 mysql [localhost:41140] {msandbox} ((none)) > show profile for query 1 ; +----------------------------+----------+ | Status | Duration | +----------------------------+----------+ | starting | 0.000220 | | checking permissions | 0.000012 | | checking permissions | 0.000008 | | Opening tables | 0.000365 | | checking permissions | 0.000009 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000005 | | checking permissions | 0.000090 | | init | 0.000163 | | checking permissions | 0.000009 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000004 | | checking permissions | 0.000046 | | System lock | 0.000024 | | optimizing | 0.000035 | | statistics | 0.000131 | | preparing | 0.000041 | | Creating tmp table | 0.000078 | | executing | 0.000120 | | checking permissions | 0.000101 | | checking permissions | 0.000044 | | checking permissions | 0.000017 | | checking permissions | 0.000046 | | end | 0.000008 | | query end | 0.000005 | | waiting for handler commit | 0.000024 | | removing tmp table | 0.000010 | | waiting for handler commit | 0.000007 | | closing tables | 0.000017 | | freeing items | 0.000037 | | cleaning up | 0.000017 | +----------------------------+----------+ # MySQL 5.7 mysql [localhost:41141] {msandbox} ((none)) > show profile for query 1 ; +----------------------+----------+ | Status | Duration | +----------------------+----------+ | starting | 0.000210 | | checking permissions | 0.000019 | | checking permissions | 0.000010 | | Opening tables | 0.000355 | | init | 0.000027 | | System lock | 0.000012 | | optimizing | 0.000009 | | statistics | 0.000027 | | preparing | 0.000024 | | executing | 0.000021 | | Opening tables | 0.000028 | | checking permissions | 0.000068 | | checking permissions | 0.000031 | | Sending data | 0.000077 | | end | 0.000009 | | query end | 0.000012 | | closing tables | 0.000006 | | removing tmp table | 0.000103 | | closing tables | 0.000013 | | freeing items | 0.000035 | | cleaning up | 0.000030 | +----------------------+----------+ 21 rows in set, 1 warning (0.00 sec) I've tried increasing table_open_cache and changing internal_tmp_mem_storage_engine to MEMORY but didn't help. How to repeat: # Deployed MySQL 5.7.29 and 8.0.19 $ dbdeployer deploy single /opt/mysql/5.7.29 $ dbdeployer deploy single /opt/mysql/8.0.19 # Created a dummy table on test database on each instance mysql> CREATE TABLE `t1` ( `c1` int(11) NOT NULL AUTO_INCREMENT, `c2` int(11) DEFAULT NULL, PRIMARY KEY (`c1`), KEY `c2` (`c2`) ) ENGINE=InnoDB ; # Executed mysqlslap on 5.7 and 8.0 with and without concurrency using several iterations and we can see a big difference between execution times $ time mysqlslap --defaults-file=./msb_5_7_29/my.sandbox.cnf --delimiter=";" --query="SHOW FULL FIELDS FROM test.t1" --create-schema=test --concurrency=1 --iterations=1000 Benchmark Average number of seconds to run all queries: 0.000 seconds Minimum number of seconds to run all queries: 0.000 seconds Maximum number of seconds to run all queries: 0.001 seconds Number of clients running queries: 1 Average number of queries per client: 1 real 0m0.480s user 0m0.045s sys 0m0.122s $ time mysqlslap --defaults-file=./msb_5_7_29/my.sandbox.cnf --delimiter=";" --query="SHOW FULL FIELDS FROM test.t1" --create-schema=test --concurrency=50 --iterations=1000 Benchmark Average number of seconds to run all queries: 0.004 seconds Minimum number of seconds to run all queries: 0.003 seconds Maximum number of seconds to run all queries: 0.011 seconds Number of clients running queries: 50 Average number of queries per client: 1 real 0m7.256s user 0m4.753s sys 0m11.983s $ time mysqlslap --defaults-file=./msb_8_0_19/my.sandbox.cnf --delimiter=";" --query="SHOW FULL FIELDS FROM test.t1" --create-schema=test --concurrency=1 --iterations=1000 Benchmark Average number of seconds to run all queries: 0.001 seconds Minimum number of seconds to run all queries: 0.001 seconds Maximum number of seconds to run all queries: 0.005 seconds Number of clients running queries: 1 Average number of queries per client: 1 real 0m1.810s user 0m0.078s sys 0m0.191s $ time mysqlslap --defaults-file=./msb_8_0_19/my.sandbox.cnf --delimiter=";" --query="SHOW FULL FIELDS FROM test.t1" --create-schema=test --concurrency=50 --iterations=1000 Benchmark Average number of seconds to run all queries: 0.011 seconds Minimum number of seconds to run all queries: 0.007 seconds Maximum number of seconds to run all queries: 0.024 seconds Number of clients running queries: 50 Average number of queries per client: 1 real 0m13.714s user 0m5.558s sys 0m13.593s