The MySQL query cache is a special buffer, where database stores the text of a SELECT statement together with the corresponding result that was sent to the client. For as long as no table that a statement refers to changes in any way, including the contents, the cached result can be re-used to answer any identical sub-sequent SELECT statements. But how to tell whether a query was executed or returned from the cache?
There are at least three ways to check it.
Method 1
MySQL exposes a number of runtime statistics that are accessible with SHOW STATUS statement. Among the long list of various counters, one is called Com_select which shows how many times a SELECT statement was executed. However if a SELECT is served from the query cache, it does not actually execute, so it is not accounted in Com_select. The conclusion must be that if a query runs, but it does not increment this value, the result was returned from the cache.
mysql> SHOW STATUS LIKE 'Com_select'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | Com_select | 7 | +---------------+-------+ mysql> SELECT * FROM a WHERE a = 4; +------+-----------+ | a | timestamp | +------+-----------+ | 4 | NULL | +------+-----------+ mysql> SHOW STATUS LIKE 'Com_select'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | Com_select | 8 | +---------------+-------+
The query was run for the first time and it had to be executed, so the counter was incremented.
mysql> SELECT * FROM a WHERE a = 4; +------+-----------+ | a | timestamp | +------+-----------+ | 4 | NULL | +------+-----------+ mysql> SHOW STATUS LIKE 'Com_select'; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | Com_select | 8 | +---------------+-------+
Running it for the second time did not change Com_select, which means the result was served from the query cache.
Method 2
MySQL 5.0 added a new feature for query profiling called... profiling. In some MySQL versions and/or releases it is available by default, in others it has to be enabled in my.cnf before it can be used. Profiling collects information about various stages of query execution along with the timings, all of which can be accessed later. All basic details about this are available in the MySQL documentation.
The profiling was enabled, so the two query runs from the previous method should be available in SHOW PROFILES:
mysql> SHOW PROFILES; +----------+------------+--------------------------------------+ | Query_ID | Duration | Query | +----------+------------+--------------------------------------+ [..] | 40 | 0.00028525 | SELECT * FROM a WHERE a = 4 | | 41 | 0.00007925 | SELECT * FROM a WHERE a = 4 | +----------+------------+--------------------------------------+ mysql> SHOW PROFILE FOR QUERY 40; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000038 | | Waiting for query cache lock | 0.000003 | | Waiting on query cache mutex | 0.000002 | | checking query cache for query | 0.000036 | | checking permissions | 0.000006 | | Opening tables | 0.000017 | | System lock | 0.000009 | | Waiting for query cache lock | 0.000002 | | Waiting on query cache mutex | 0.000018 | | init | 0.000019 | | optimizing | 0.000007 | | statistics | 0.000012 | | preparing | 0.000011 | | executing | 0.000002 | | Sending data | 0.000046 | | end | 0.000003 | | query end | 0.000005 | | closing tables | 0.000007 | | freeing items | 0.000008 | | Waiting for query cache lock | 0.000002 | | Waiting on query cache mutex | 0.000002 | | freeing items | 0.000018 | | Waiting for query cache lock | 0.000002 | | Waiting on query cache mutex | 0.000002 | | freeing items | 0.000002 | | storing result in query cache | 0.000004 | | logging slow query | 0.000002 | | cleaning up | 0.000002 | +--------------------------------+----------+
The profile of run number one, which did actually execute, shows a nice trace of query cache lookup, the execution itself and finally storing result in the cache.
mysql> SHOW PROFILE FOR QUERY 41; +--------------------------------+----------+ | Status | Duration | +--------------------------------+----------+ | starting | 0.000034 | | Waiting for query cache lock | 0.000003 | | Waiting on query cache mutex | 0.000002 | | checking query cache for query | 0.000006 | | checking privileges on cached | 0.000004 | | checking permissions | 0.000006 | | sending cached result to clien | 0.000020 | | logging slow query | 0.000002 | | cleaning up | 0.000003 | +--------------------------------+----------+
The profile of run number two, which was served from the query cache, is much shorter and even explicitly states one of the stages was 'sending cached result to client'. Done.
Method 3
Some flavors of MySQL, such as Percona Server, come with the extended slow logging feature (which I largely authored back in 2007). It can be used to see not only whether a query executed or was served from the query cache, but a lot more information about each query too. So if the slow log is enabled, it can be tuned to log whatever is needed.
In the simplest case it might be enough to just have all the queries for the current session logged, just to check about the query cache.
mysql> SET SESSION long_query_time=0; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM a WHERE a = 4; +------+-----------+ | a | timestamp | +------+-----------+ | 4 | NULL | +------+-----------+ 1 row in set (0.00 sec) mysql> SELECT * FROM a WHERE a = 4; +------+-----------+ | a | timestamp | +------+-----------+ | 4 | NULL | +------+-----------+ 1 row in set (0.00 sec)
The long_query_time setting tells MySQL how long a query must run before it can be logged into the slow log. In this case it will only apply to the current session and not globally. Following that are two runs of the same query - one expected to execute and one to be returned from the query cache. Here is what appeared in the log:
# Time: 120403 13:48:08 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: test Last_errno: 0 Killed: 0 # Query_time: 0.000291 Lock_time: 0.000112 Rows_sent: 1 Rows_examined: 4 Rows_affected: 0 Rows_read: 1 # Bytes_sent: 114 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # InnoDB_trx_id: 118900 # QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No # Filesort: No Filesort_on_disk: No Merge_passes: 0 SET timestamp=1333453688; SELECT * FROM a WHERE a = 4; # Time: 120403 13:48:09 # User@Host: root[root] @ localhost [] # Thread_id: 2 Schema: test Last_errno: 0 Killed: 0 # Query_time: 0.000032 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 Rows_affected: 0 Rows_read: 0 # Bytes_sent: 114 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # QC_Hit: Yes Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No # Filesort: No Filesort_on_disk: No Merge_passes: 0 SET timestamp=1333453689; SELECT * FROM a WHERE a = 4;
The QC_Hit value shows whether query cache was used or not.
Comparing the two outputs a bit more carefully reveals further differences - in Rows_sent, Rows_examined, etc. If these are zero, but it is certain that a query must have examined and/or returned at least some rows, it also suggests that the cache was used to provide the answer. And while it is not a fully reliable information, this actually works even with MySQL versions that do not have the extended slow query log!