MySQL slow query - "Waiting for query cache lock"

Question

I am running a simple query on a simple table on the same machine as the server running 5.5. It is taking 22sec to return ~7000 rows from a 20 million row table. Upon profiling most of the time is taken up by multiple "Waiting for query cache lock". What is "Waiting for query cache lock" and why is this query taking so long? Is it something with the way I set up the server?

Here is the profile (note the time for the operation is actually from the row below as stated here):

mysql> show profile for query 4; +--------------------------------+----------+ | Status                         | Duration | +--------------------------------+----------+ | starting                       | 0.000015 | | Waiting for query cache lock   | 0.000003 | | checking query cache for query | 0.000045 | | checking permissions           | 0.000006 | | Opening tables                 | 0.000027 | | System lock                    | 0.000007 | | Waiting for query cache lock   | 0.000032 | | init                           | 0.000018 | | optimizing                     | 0.000008 | | statistics                     | 0.033109 | | preparing                      | 0.000019 | | executing                      | 0.000002 | | Sending data                   | 4.575480 | | Waiting for query cache lock   | 0.000005 | | Sending data                   | 5.527728 | | Waiting for query cache lock   | 0.000005 | | Sending data                   | 5.743041 | | Waiting for query cache lock   | 0.000004 | | Sending data                   | 6.191706 | | end                            | 0.000007 | | query end                      | 0.000005 | | closing tables                 | 0.000028 | | freeing items                  | 0.000008 | | Waiting for query cache lock   | 0.000002 | | freeing items                  | 0.000182 | | Waiting for query cache lock   | 0.000002 | | freeing items                  | 0.000002 | | storing result in query cache  | 0.000004 | | logging slow query             | 0.000001 | | logging slow query             | 0.000002 | | cleaning up                    | 0.000003 | +--------------------------------+----------+ 

Here is the table:

mysql> SHOW CREATE TABLE prvol;  "Table","Create Table" "prvol","CREATE TABLE `prvol` (   `ticker` varchar(10) DEFAULT NULL,   `date` date DEFAULT NULL,   `close` float unsigned DEFAULT NULL,   KEY `Index 1` (`date`) ) ENGINE=InnoDB DEFAULT CHARSET=latin1" 

Here is the query:

mysql> select close from prvol where date = '20100203'; 

EDIT: After running with SQL_NO_CACHE, all the time is now in the execution. Could this just be normal for a table this size on a 2.4GHz, 3GB ram machine?

+----------------------+-----------+ | Status               | Duration  | +----------------------+-----------+ | starting             |  0.000052 | | checking permissions |  0.000007 | | Opening tables       |  0.000027 | | System lock          |  0.000008 | | init                 |  0.000019 | | optimizing           |  0.000008 | | statistics           |  0.034766 | | preparing            |  0.000011 | | executing            |  0.000002 | | Sending data         | 22.071324 | | end                  |  0.000012 | | query end            |  0.000005 | | closing tables       |  0.000020 | | freeing items        |  0.000170 | | logging slow query   |  0.000001 | | logging slow query   |  0.000003 | | cleaning up          |  0.000004 | +----------------------+-----------+ 

EDIT: Include results of explain.

mysql> explain extended select cp from prvol where date = '20100208'; +----+-------------+-------+------+---------------+---------+---------+-------+------+----------+-------------+ | id | select_type | table | type | possible_keys | key     | key_len | ref   |rows  | filtered | Extra       | +----+-------------+-------+------+---------------+---------+---------+-------+------+----------+-------------+ |  1 | SIMPLE      | prvol | ref  | Index 1       | Index 1 | 4       | const |6868  |   100.00 | Using where | +----+-------------+-------+------+---------------+---------+---------+-------+------+----------+-------------+ 1 row in set, 1 warning (0.08 sec) 

Answer 1

I solved my slow query problem. To summarize the problem, it was taking 22sec to query 7000 rows from a 20mln row, 1.7GB indexed table. The problem was that the cache was too small and the query had to go to disk for every query. I would think the disk access would be faster than what I was seeing because I was going off an indexed column so the amount of data read off disk should have been small. But I'm guessing there is a lot of overhead with accessing the InnoDB storage on disk.

Once I set innodb_buffer_pool_size=1024M in the my.ini file, the initial query would take a long time, but all subsequent queries would finish in under a second.

Unfortunately, the profiling didn't really help.

Answer 2

This is a known problem with MySQL. It's really well described here:

https://web.archive.org/web/20160129162137/http://www.psce.com/blog/kb/how-query-cache-can-cause-performance-problems/

Query cache can help you a lot but at the same time it can become a bottleneck.