MySQL Bugs: #60801: Select Query is too much slow and taking upto 23 seconds to complete

Bug #60801	Select Query is too much slow and taking upto 23 seconds to complete
Submitted:	8 Apr 2011 3:51	Modified:	9 May 2011 3:59
Reporter:	Devang Modi	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Query Cache	Severity:	S2 (Serious)
Version:	mysql Ver 14.12 Distrib 5.0.45	OS:	Linux (Red Hat Enterprise Linux Server release 5.3 )
Assigned to:		CPU Architecture:	Any
Tags:	512MB, cache, query, slow, with

Description:
Dear Sir;

We have a very simple query working on primary key. 
Sometimes it starts taking more than 23 seconds to complete it task, although the table is having only 212 records.

We produced Query Profiling we found below surprising results

+--------------------------------+-----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+---------------------------+---------------+-------------+
| Status                         | Duration  | CPU_user  | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function           | Source_file   | Source_line |
+--------------------------------+-----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+---------------------------+---------------+-------------+
| (initialization)               | 23.892326 | 23.981355 | 0.053992   |               805 |                1250 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | send_result_to_client     | sql_cache.cc  |        1099 | 
| checking query cache for query | 0.000107  | 0         | 0          |                 1 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | open_tables               | sql_base.cc   |        2629 | 
| Opening tables                 | 0.000012  | 0         | 0          |                 1 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables         | lock.cc       |         153 | 
| System lock                    | 0.000005  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_lock_tables         | lock.cc       |         162 | 
| Table lock                     | 0.000048  | 0         | 0          |                 2 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_select              | sql_select.cc |        2242 | 
| init                           | 0.000015  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize                  | sql_select.cc |         745 | 
| optimizing                     | 0.00001   | 0         | 0          |                 1 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize                  | sql_select.cc |         904 | 
| statistics                     | 0.000034  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | optimize                  | sql_select.cc |         914 | 
| preparing                      | 0.000013  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                      | sql_select.cc |        1565 | 
| executing                      | 0.000005  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | exec                      | sql_select.cc |        2083 | 
| Sending data                   | 0.003907  | 0.010998  | 0          |                55 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_select              | sql_select.cc |        2287 | 
| end                            | 0.000007  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_execute_command     | sql_parse.cc  |        5122 | 
| query end                      | 0.000004  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | query_cache_end_of_result | sql_cache.cc  |         729 | 
| storing result in query cache  | 0.000217  | 0         | 0          |                 4 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | mysql_parse               | sql_parse.cc  |        6116 | 
| freeing items                  | 0.000008  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command          | sql_parse.cc  |        2146 | 
| closing tables                 | 0.000007  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | log_slow_statement        | sql_parse.cc  |        2204 | 
| logging slow query             | 0.000003  | 0         | 0          |                 0 |                   0 |            0 |             0 |             0 |                 0 |                 0 |                 0 |     0 | dispatch_command          | sql_parse.cc  |        2169 | 
+--------------------------------+-----------+-----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+---------------------------+---------------+-------------+

Now our server configuration is 4 Xeon Processor with 36 Gigabytes of RAM and serving only MySQL datIabase.
Database storage engine is mix Innodb and MyISAM.
InnoDB database size is roughly 8 gigabbytes while MyISAM is 72 Gigabytes.
The query cache size is 512 Megabytes RAM.
The query example is

SELECT charvar FROM system WHERE recid = "SP004";

In above query table system is related with "innodb"
Total records in table are 212
On recid primary key index has been set.

Here I wanted to know that
1. Is there any bug attached behind this slowness?
2. If yes what should we do to come out from it
3. If not a bug than is it high query cache is making problem for us?

thanks

For your input

Devang

How to repeat:
We can discuss further on this before you really spend your valuable time behind this.

Your query cache is probably too big, and it becomes fragmented eventually. Please, make it smaller, 128M, and check if this problem will ever happen again.

Dear Sir;

thanks for your valuable input , tomorrow during our weekly maintenance we will apply your suggestion and i will again share output with you.

thanks

Devang

Check http://dev.mysql.com/doc/refman/5.0/en/server-system-variables.html#sysvar_query_cache_siz.... 

You can change the size dynamically, without server restart, using:

set global query_cache_size=128*1024*1024;

Dear sir;

you are correct but as part of business policy we are doing this normally during in weekly maintenance.

thanks for your favor and guideline

Devang

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Dear Sir;

Thanks a lot for your guidelines.

We were able to solve the issue by setting up Cache Size to 128 Megabytes instead of 512 Megabytes.

please accept our warm regards and thanks on this.

Devang Modi & team