I am running MySQL version 5.1.69 and the tables in question are MyISAM.
I have a very simple table:
CREATE TABLE `tbl` (
`ID` int(11) NOT NULL AUTO_INCREMENT,
`otherID` int(11) NOT NULL,
`addedDTM` datetime NOT NULL,
`moveFlag` tinyint(1) NOT NULL,
`stopFlag` tinyint(1) NOT NULL,
PRIMARY KEY (`ID`),
KEY `idx_otherID` (`otherID`),
KEY `idx_addedDTM` (`addedDTM`)
)
It gets a lot of traffic to the table, but is constantly at ~5000 records. The table gets lots of inserts/updates/deletes every second and the cardinality of the keys always shows the correct values.
Roughly 2% of the time, there is a slow SELECT or UPDATE that takes > 0.2 seconds and regularly takes > 1 second. It seems to happen randomly but can be recreated by running the same query many times until it runs slow.
The SELECT query is:
SELECT ID, otherID, addedDTM FROM tbl WHERE moveFlag=1;
The UPDATE query is:
UPDATE tbl SET addedDTM=NOW(), moveFlag=1, stopFlag=0 WHERE ID=-2;
Both of these queries run in < 1ms the majority of the time, here are the profiling traces:
SELECT
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| 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 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| starting | 0.000032 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Opening tables | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_base.cc | 4615 |
| System lock | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 260 |
| Table lock | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 271 |
| init | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2539 |
| optimizing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 835 |
| statistics | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1026 |
| preparing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1048 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1791 |
| Sending data | 0.000468 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2349 |
| end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2585 |
| query end | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5130 |
| freeing items | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 6154 |
| logging slow query | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1742 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1710 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
UPDATE
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| 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 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| starting | 0.000034 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| checking permissions | 0.000011 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5366 |
| Opening tables | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_base.cc | 4615 |
| System lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 260 |
| Table lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 271 |
| init | 0.000028 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 292 |
| Updating | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 605 |
| end | 0.000021 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 837 |
| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5130 |
| freeing items | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 6154 |
| logging slow query | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1742 |
| cleaning up | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1710 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
When they run slow, they show the following profile traces:
SELECT
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| 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 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| starting | 0.000035 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| Opening tables | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_base.cc | 4615 |
| System lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 260 |
| Table lock | 1.147320 | 0.006999 | 0.003000 | 125 | 0 | 0 | 56 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 271 |
| init | 0.000024 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2539 |
| optimizing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 835 |
| statistics | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1026 |
| preparing | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1048 |
| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 1791 |
| Sending data | 0.000475 | 0.000999 | 0.000000 | 11 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2349 |
| end | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_select.cc | 2585 |
| query end | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5130 |
| freeing items | 0.000008 | 0.000000 | 0.000000 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 6154 |
| logging slow query | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1742 |
| cleaning up | 0.000003 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1710 |
+--------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
UPDATE
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| 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 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
| starting | 0.000031 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL | NULL |
| checking permissions | 0.000015 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5366 |
| Opening tables | 0.000012 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_base.cc | 4615 |
| System lock | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 260 |
| Table lock | 0.220138 | 0.002000 | 0.002000 | 40 | 0 | 0 | 56 | 0 | 0 | 0 | 0 | 0 | unknown function | lock.cc | 271 |
| init | 0.000029 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 292 |
| Updating | 0.000009 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 605 |
| end | 0.000022 | 0.000000 | 0.000000 | 1 | 0 | 0 | 8 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_update.cc | 837 |
| query end | 0.000006 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 5130 |
| freeing items | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 6154 |
| logging slow query | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1742 |
| cleaning up | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | unknown function | sql_parse.cc | 1710 |
+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+------------------+---------------+-------------+
What does Context_voluntary and Block_ops_out mean? These seem to be what is taking up the time when the query runs slow. Is there something that can be done to reduce these?
Best Answer
Switch to InnoDB; it does not lock the table.
Here's one thing that can happen in MyISAM:
SELECT ... WHERE moveFlag=1-- no index usable, so must do table scan.UPDATE, but hangs waiting for select (#1) to finish.SELECT, but it hangs waiting forUPDATE(#2) to finish.This kind of mess is eliminated when using InnoDB.
(I find profiles and traces to usually be useless.)
Let's check some more things... How much RAM? Value of
key_buffer_size?SHOW TABLE STATUS LIKE 'tbl';