Bug #71205 Queries to P_S seems to pass extra stages related to query cache

Submitted:	22 Dec 2013 16:04	Modified:	27 Dec 2013 8:00
Reporter:	Valeriy Kravchuk	Email Updates:
Status:	Not a Bug	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S3 (Non-critical)
Version:	5.6.14	OS:	Any
Assigned to:		CPU Architecture:	Any

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.

The query cache is checked before the query is parsed, so it does not have information on what is the type of the table that will be accessed.

Thank you for the report.

Davi is correct and this is not a bug.

Should not we then explicitly recommend in the manual to add sql_no_cache no each query against P_S, to avoid extra locking and time wasted on the query cache (if it is enabled)?

Page generated in 0.041 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.