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

[22 Dec 2013 16:04] Valeriy Kravchuk
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.
[22 Dec 2013 18:37] Davi Arnaut
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.
[24 Dec 2013 17:22] Sveta Smirnova
Thank you for the report.

Davi is correct and this is not a bug.
[27 Dec 2013 8:00] Valeriy Kravchuk
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)?