Description:
While working on a test case for bug #71204 I've noted (using SHOW PROFILE for query to P_S) that some queries to P_S tables seem to pass stages related to query cache and waste some time there:
mysql> show profiles\G
...
*************************** 2. row ***************************
Query_ID: 2
Duration: 0.00572600
Query: SELECT event_name, timer_wait/1000000000 wait_ms
FROM events_stages_history_long AS stages
JOIN (SELECT event_id
FROM events_statements_history_long
ORDER BY event_id DESC limit 1) AS statements
ON stages.nesting_event_id
...
*************************** 6. row ***************************
Query_ID: 6
Duration: 0.00564600
Query: SELECT sql_no_cache event_name, timer_wait/1000000000 wait_ms
FROM events_stages_history_long AS stages
JOIN (SELECT event_id
FROM events_statements_history_long
ORDER BY event_id DESC limit 1) AS statements
ON stages.nest
...
mysql> show profile for query 6;
+----------------------+----------+
| Status | Duration |
+----------------------+----------+
| starting | 0.000243 |
| checking permissions | 0.000017 |
| checking permissions | 0.000038 |
| Opening tables | 0.000778 |
| init | 0.000061 |
| System lock | 0.000022 |
| optimizing | 0.000009 |
| optimizing | 0.000012 |
| statistics | 0.000036 |
| preparing | 0.000030 |
| Sorting result | 0.000036 |
| executing | 0.000007 |
| Sending data | 0.000007 |
| Creating sort index | 0.002224 |
| statistics | 0.000089 |
| preparing | 0.000041 |
| Sorting result | 0.000010 |
| executing | 0.000007 |
| Sending data | 0.000026 |
| Creating sort index | 0.001427 |
| end | 0.000032 |
| query end | 0.000012 |
| closing tables | 0.000007 |
| removing tmp table | 0.000026 |
| closing tables | 0.000039 |
| freeing items | 0.000360 |
| cleaning up | 0.000055 |
+----------------------+----------+
27 rows in set, 1 warning (0.00 sec)
mysql> show profile for query 2;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000097 |
| Waiting for query cache lock | 0.000015 |
| init | 0.000008 |
| checking query cache for query | 0.000449 |
| checking permissions | 0.000013 |
| checking permissions | 0.000030 |
| Opening tables | 0.000482 |
| init | 0.000060 |
| System lock | 0.000024 |
| optimizing | 0.000009 |
| optimizing | 0.000012 |
| statistics | 0.000038 |
| preparing | 0.000033 |
| Sorting result | 0.000042 |
| executing | 0.000008 |
| Sending data | 0.000007 |
| Creating sort index | 0.002135 |
| statistics | 0.000088 |
| preparing | 0.000040 |
| Sorting result | 0.000009 |
| executing | 0.000007 |
| Sending data | 0.000027 |
| Creating sort index | 0.000906 |
| end | 0.000033 |
| query end | 0.000013 |
| closing tables | 0.000006 |
| removing tmp table | 0.000026 |
| closing tables | 0.000041 |
| freeing items | 0.000475 |
| cleaning up | 0.000596 |
+--------------------------------+----------+
30 rows in set, 1 warning (0.00 sec)
Note extra stages:
| Waiting for query cache lock | 0.000015 |
...
| checking query cache for query | 0.000449 |
clearly related to the query cache for the query without SQL_NO_CACHE above.
I see no good reason for any query to PERFORMANCE_SCHEMA to access query cache in any way - they never should deal with the query cache, as they have to return live performance results. So, I'd expect that by default they should work as if SQL_NO_CACHE is provided, while we see clear difference above.
How to repeat:
Start with a test case for bug #71204 on server with query cache enabled, then, with profiling enabled, execute two queries trying to get stages information for the same last query executed:
SELECT event_name, timer_wait/1000000000 wait_ms
FROM events_stages_history_long AS stages
JOIN (SELECT event_id
FROM events_statements_history_long
ORDER BY event_id DESC limit 1) AS statements
ON stages.nesting_event_id = statements.event_id
ORDER BY stages.event_id;
SELECT sql_no_cache event_name, timer_wait/1000000000 wait_ms
FROM events_stages_history_long AS stages
JOIN (SELECT event_id
FROM events_statements_history_long
ORDER BY event_id DESC limit 1) AS statements
ON stages.nesting_event_id = statements.event_id
ORDER BY stages.event_id;
Then find them by numbers in the output of SHOW PROFILES and compare their profiles. Alternatively, try to study stages of their execution using P_S maybe :)
Check that query without explicit SQL_NO_CACHE seems to spend some time on stages related to the query cache, while in both cases result is NOT taken from the cache and is NOT cached:
mysql> show global status like 'Qcache%';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 1031448 |
| Qcache_hits | 0 |
| Qcache_inserts | 0 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 23 |
| Qcache_queries_in_cache | 0 |
| Qcache_total_blocks | 1 |
+-------------------------+---------+
8 rows in set (0.00 sec)
mysql> SELECT event_name, timer_wait/1000000000 wait_ms
-> FROM events_stages_history_long AS stages
-> JOIN (SELECT event_id
-> FROM events_statements_history_long
-> ORDER BY event_id DESC limit 1) AS statements
-> ON stages.nesting_event_id = statements.event_id
-> ORDER BY stages.event_id;
+--------------------------------+---------+
| event_name | wait_ms |
+--------------------------------+---------+
| stage/sql/init | 0.3264 |
| stage/sql/checking permissions | 0.0349 |
| stage/sql/Opening tables | 0.4866 |
| stage/sql/init | 0.0328 |
| stage/sql/System lock | 0.0154 |
| stage/sql/optimizing | 0.0123 |
| stage/sql/statistics | 0.0370 |
| stage/sql/preparing | 0.0349 |
| stage/sql/executing | 0.7237 |
| stage/sql/Sending data | 0.0729 |
| stage/sql/end | 0.0123 |
| stage/sql/query end | 0.0092 |
| stage/sql/closing tables | 0.0062 |
| stage/sql/removing tmp table | 0.0246 |
| stage/sql/freeing items | 0.2833 |
| stage/sql/cleaning up | 0.0072 |
+--------------------------------+---------+
16 rows in set (0.01 sec)
mysql> show global status like 'Qcache%';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 1031448 |
| Qcache_hits | 0 |
| Qcache_inserts | 0 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 24 |
| Qcache_queries_in_cache | 0 |
| Qcache_total_blocks | 1 |
+-------------------------+---------+
8 rows in set (0.00 sec)
mysql> SELECT sql_no_cache event_name, timer_wait/1000000000 wait_ms
-> FROM events_stages_history_long AS stages
-> JOIN (SELECT event_id
-> FROM events_statements_history_long
-> ORDER BY event_id DESC limit 1) AS statements
-> ON stages.nesting_event_id = statements.event_id
-> ORDER BY stages.event_id;
+--------------------------------+---------+
| event_name | wait_ms |
+--------------------------------+---------+
| stage/sql/init | 0.1571 |
| stage/sql/checking permissions | 0.0267 |
| stage/sql/Opening tables | 0.4958 |
| stage/sql/init | 0.0308 |
| stage/sql/System lock | 0.0144 |
| stage/sql/optimizing | 0.0123 |
| stage/sql/statistics | 0.0359 |
| stage/sql/preparing | 0.0308 |
| stage/sql/executing | 0.6354 |
| stage/sql/Sending data | 0.0657 |
| stage/sql/end | 0.0113 |
| stage/sql/query end | 0.0092 |
| stage/sql/closing tables | 0.0072 |
| stage/sql/removing tmp table | 0.0226 |
| stage/sql/freeing items | 0.3234 |
| stage/sql/cleaning up | 0.0072 |
+--------------------------------+---------+
16 rows in set (0.01 sec)
mysql> show global status like 'Qcache%';
+-------------------------+---------+
| Variable_name | Value |
+-------------------------+---------+
| Qcache_free_blocks | 1 |
| Qcache_free_memory | 1031448 |
| Qcache_hits | 0 |
| Qcache_inserts | 0 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 25 |
| Qcache_queries_in_cache | 0 |
| Qcache_total_blocks | 1 |
+-------------------------+---------+
8 rows in set (0.00 sec)
Suggested fix:
Make queries to P_S work by default in the same way as they do with explicit SQL_NO_CACHE added. There is no any good reason for them to access query cache. Doing this may have some extra performance impact for systems that use query cache a lot.
