Simple, small table (5000 rows) with around 2% slow queries, with high table lock time - context_voluntary and block_ops_out

Question

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?

Answer 1

Switch to InnoDB; it does not lock the table.

Here's one thing that can happen in MyISAM:

• Connection 1 does SELECT ... WHERE moveFlag=1 -- no index usable, so must do table scan.
• Connection 2 does UPDATE, but hangs waiting for select (#1) to finish.
• Connection 3 does a SELECT, but it hangs waiting for UPDATE (#2) to finish.
• Etc.

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';

Answer 2

CONTEXT_VOLUNTARY and CONTEXT_INVOLUNTARY indicate how many voluntary and involuntary context switches occurred (source) which confirms you're waiting on locks.

Table is MyISAM, so writes block other writes and reads.

UPDATEs lock the table exclusively (blocking out other UPDATEs and SELECTs). Therefore, other queries will be queued. The optimum execution order would be:

• one update
• seleral selects in parallel
• one update
• etc

However, depending on the number of updates and the order in which they come out of the queue, you might get only one update, then one select, then one update... and no parallelization of SELECTs at all.

At some point, one of the queries needs to wait on IO, which is slow. Or you do a backup. Or the server is loaded. Or you do another query (like a JOIN) which uses this table and locks it for a little while. Then all hell breaks loose.

When a MyISAM table takes lots of read/write queries, this always eventually happens. You'll get random slowdowns with lots of locking, at a traffic level which should intuitively be fine.

Switch to InnoDB, or another system which holds your cache table in RAM.