MySQL Bugs: #47277: Query stuck "Sending data" locks table; query cache off; MyISAM

Bug #47277	Query stuck "Sending data" locks table; query cache off; MyISAM
Submitted:	11 Sep 2009 17:13	Modified:	26 Apr 2010 10:41
Reporter:	Brandon Low	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.1.38	OS:	FreeBSD (7.2-RELEASE)
Assigned to:		CPU Architecture:	Any

Description:
Similar problem description to http://bugs.mysql.com/bug.php?id=45544 but query cache is already off here.  Also behaves a bit like http://bugs.mysql.com/bug.php?id=32149 but we are on MyISAM not InnoDB.

I have a table with about 27M rows (status below) which I am rapidly populating.  I have 16 threads working on populating this table.  Their query pattern is: Select N rows by ID, some of which will exist and some will not.  For each of the N rows, INSERT or UPDATE as needed.

When N is relatively small (100) performance is good, but after between 1 and 12 hours, a select will stick in 'Sending data' and the table will (apparently) deadlock.  At this point, killing the stuck queries does not free up the table immediately.  The original culprit will take between 1 and infinite hours to die.

When N is relatively large (250) performance is unacceptably bad, but the deadlock does not occur.

What appears to happen is that during the sending data phase of the select, that thread holds a table lock, and tries to take some other kind of metadata lock, but updates or inserts take the metadata lock and then try to take the table lock.  I don't know exactly how this process might work, but that's how it seems to me.

I'm pasting below a show processlist and other possibly interesting data.  It should be noted that this particular show processlist has two queries stuck in sending data, but this is the first time I've seen that particular behavior.

mysql> show processlist;
+----+-----------+----------------------+---------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+
| Id | User      | Host                 | db      | Command | Time  | State        | Info                                                                                                 |
+----+-----------+----------------------+---------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+
|  9 | metricsrw | 192.168.51.108:49513 | metrics | Query   | 53664 | Sending data | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 10 | metricsrw | 192.168.51.108:49514 | metrics | Query   | 53653 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 11 | metricsrw | 192.168.51.108:49515 | metrics | Query   | 53649 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 12 | metricsrw | 192.168.51.108:49516 | metrics | Query   | 53657 | Locked       | UPDATE air_schedule_price SET valid_price_checks=2, updated_at=CURRENT_TIMESTAMP WHERE air_schedule_ |
| 13 | metricsrw | 192.168.51.108:49517 | metrics | Query   | 53654 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 14 | metricsrw | 192.168.51.244:61350 | metrics | Query   | 53651 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 15 | metricsrw | 192.168.51.244:62833 | metrics | Query   | 53659 | Locked       | UPDATE air_schedule_price SET valid_price_checks=16, average_price=1005.80133333333, updated_at=CURR |
| 16 | metricsrw | 192.168.51.108:49518 | metrics | Query   | 53649 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 17 | metricsrw | 192.168.51.244:61813 | metrics | Query   | 53658 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 18 | metricsrw | 192.168.51.108:49519 | metrics | Query   | 53655 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 19 | metricsrw | 192.168.51.244:58793 | metrics | Query   | 53658 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 20 | metricsrw | 192.168.51.108:49520 | metrics | Query   | 53657 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 21 | metricsrw | 192.168.51.244:55723 | metrics | Query   | 53652 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 22 | metricsrw | 192.168.51.244:62564 | metrics | Query   | 53653 | Locked       | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 23 | metricsrw | 192.168.51.244:58695 | metrics | Query   | 53657 | Locked       | UPDATE air_schedule_price SET valid_price_checks=4, average_price=650, updated_at=CURRENT_TIMESTAMP  |
| 24 | metricsrw | 192.168.51.244:64183 | metrics | Query   | 53663 | Sending data | SELECT air_schedule_price.origin_airport_code AS air_schedule_price_origin_airport_code, air_schedul |
| 29 | metricsrw | 192.168.51.200:63156 | metrics | Query   |     0 | NULL         | show processlist                                                                                     |
+----+-----------+----------------------+---------+---------+-------+--------------+------------------------------------------------------------------------------------------------------+
17 rows in set (0.00 sec)

mysql> show table status like 'air_schedule_price';
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
| Name               | Engine | Version | Row_format | Rows     | Avg_row_length | Data_length | Max_data_length   | Index_length | Data_free | Auto_increment | Create_time         | Update_time         | Check_time | Collation         | Checksum | Create_options | Comment |
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
| air_schedule_price | MyISAM |      10 | Fixed      | 27450312 |             57 |  1564667784 | 16044073672507391 |   1939355648 |         0 |       27450313 | 2009-08-11 21:29:16 | 2009-09-11 01:56:47 | NULL       | latin1_swedish_ci |     NULL |                |         |
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
1 row in set (0.00 sec)

mysql> show variables like '%cache%';
+------------------------------+----------------------+
| Variable_name                | Value                |
+------------------------------+----------------------+
| binlog_cache_size            | 32768                |
| have_query_cache             | YES                  |
| key_cache_age_threshold      | 300                  |
| key_cache_block_size         | 1024                 |
| key_cache_division_limit     | 100                  |
| max_binlog_cache_size        | 18446744073709547520 |
| query_cache_limit            | 1048576              |
| query_cache_min_res_unit     | 4096                 |
| query_cache_size             | 0                    |
| query_cache_type             | ON                   |
| query_cache_wlock_invalidate | OFF                  |
| table_definition_cache       | 256                  |
| table_open_cache             | 64                   |
| thread_cache_size            | 500                  |
+------------------------------+----------------------+
14 rows in set (0.00 sec)

How to repeat:
I don't have a precise way to replicate this bug yet, but it seems like connecting to mysql over a relatively slow link and replicating the query pattern described above should make it likely.

Slight correction -- the rows are selected by unique index, not by id in the problematic table.

Thank you for the problem report. Please, send entire problematic SELECT, EXPLAIN results for it, SHOW CREATE TABLE and SHOW TABLE STATUS results for the table(s) used.

| air_schedule_price | CREATE TABLE `air_schedule_price` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `oac` char(4) DEFAULT NULL,
  `dac` char(4) DEFAULT NULL,
  `ac` char(3) DEFAULT NULL,
  `t` enum('U','O','R','M') DEFAULT NULL,
  `dd` date DEFAULT NULL,
  `do` int(11) DEFAULT NULL,   `fc` enum('M','U','F','B','C') DEFAULT NULL,
  `vpc` int(11) NOT NULL DEFAULT '0',
  `ap` float NOT NULL,
  `lp` float NOT NULL,
  `hp` float NOT NULL,
  `created_at` datetime NOT NULL,
  `updated_at` datetime NOT NULL,
  PRIMARY KEY (`id`),  UNIQUE KEY `oac` (`oac`,`dac`,`ac`,`t`,`dd`,`do`,`fc`)
) ENGINE=MyISAM AUTO_INCREMENT=27450313 DEFAULT CHARSET=latin1 | 

SELECT air_schedule_price.oac AS air_schedule_price_oac, air_schedule_price.dac AS air_schedule_price_dac, air_schedule_price.ac AS air_schedule_price_ac, air_schedule_price.dd AS air_schedule_price_dd, air_schedule_price.do AS air_schedule_price_do, air_schedule_price.fc AS air_schedule_price_fc, air_schedule_price.vpc AS air_schedule_price_vpc, air_schedule_price.ap AS air_schedule_price_ap, air_schedule_price.lp AS air_schedule_price_lp, air_schedule_price.hp AS air_schedule_price_hp, air_schedule_price.created_at AS air_schedule_price_created_at, air_schedule_price.updated_at AS air_schedule_price_updated_at, air_schedule_price.id AS air_schedule_price_id, air_schedule_price.t AS air_schedule_price_t
FROM air_schedule_price
WHERE (air_schedule_price.oac,air_schedule_price.dac,air_schedule_price.ac,air_schedule_price.t,air_schedule_price.dd,air_schedule_price.do,air_schedule_price.fc) = (***VALUES***) OR ***99 more OR'd UniqueKey Values***

(In the above I shortened the names of everything and omitted the specific values for brevity)

I still would like to see EXPLAIN results for the real query. Please, provide it.

Please also send us UPDATE statement you use.

mysql> source explain.txt
PAGER set to stdout
PAGER set to stdout
+----+-------------+--------------------+-------+---------------+-----+---------+------+-------+-------------+
| id | select_type | table              | type  | possible_keys | key | key_len | ref  | rows  | Extra       | 
+----+-------------+--------------------+-------+---------------+-----+---------+------+-------+-------------+
|  1 | SIMPLE      | air_schedule_price | range | oac           | oac | 27      | NULL | 61642 | Using where |
+----+-------------+--------------------+-------+---------------+-----+---------+------+-------+-------------+
1 row in set (5.34 sec)

UPDATE air_schedule_price SET vpc=2, updated_at=CURRENT_TIMESTAMP WHERE air_schedule_price.id = 13886130;

Please, send also the results of:

show table status like 'air_schedule_price'\G

and the results of:

select count(*) from air_schedule_price 
  where <the same where clause with 100 unique keys ORed...>;

I included the table status in the original report and the database has been in use since the original bug report.  

Here are the current results of what you asked for:
mysql> source count.txt
PAGER set to stdout
+----------+
| count(*) |
+----------+
|       94 | 
+----------+
1 row in set (0.91 sec)

mysql> show table status like 'air_schedule_price';
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
| Name               | Engine | Version | Row_format | Rows     | Avg_row_length | Data_length | Max_data_length   | Index_length | Data_free | Auto_increment | Create_time         | Update_time         | Check_time | Collation         | Checksum | Create_options | Comment |
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
| air_schedule_price | MyISAM |      10 | Fixed      | 34652414 |             57 |  1975187598 | 16044073672507391 |   2458752000 |         0 |       34652415 | 2009-08-11 21:29:16 | 2009-09-16 14:15:48 | NULL       | latin1_swedish_ci |     NULL |                |         | 
+--------------------+--------+---------+------------+----------+----------------+-------------+-------------------+--------------+-----------+----------------+---------------------+---------------------+------------+-------------------+----------+----------------+---------+
1 row in set (0.01 sec)

Just an update -- this problem is persisting.  It originally presented on MySQL 5.1.36, which I forgot to mention in the original report.  I have also now seen the problem raise its head even when using only 8 threads rather than 16.  It took nearly a week to manifest with the reduced thread count, however.

This could be a duplicate of bug #43758

Susanne: I don't agree that it is a duplicate of bug #43758 since Brandon states that the query cache is off (ie query_cache_size=0).

Please, check if this problem is repeatable with a newer version, 5.1.41.

I'm unable to continue testing this at this time as I am no longer working with the company that had the problem.  I have forwarded the bug description to them in case they want to continue investigating with you.  Thanks!

Thank you for the feedback.

Will wait news from your colleagues if any. Please also ask them if hang is still repeatable to attach gdb to running mysqld process, then run `thread apply all bt full`, so we can see what going on: problem is still not repeatable on our side.

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".

I am running into this issue on 5.1.41:

mysql> select @@version;
+------------------+
| @@version        |
+------------------+
| 5.1.41-community |
+------------------+
1 row in set (0.00 sec)

This also appears on a large (over 15 million rows) MyISAM table after an INSERT DELAYED is being run, it takes about 15 seconds to free the items.  The query cache is indeed off:

mysql> show global variables like 'query_cache%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_type             | OFF     |
| query_cache_wlock_invalidate | OFF     |
+------------------------------+---------+
5 rows in set (0.00 sec)

The only threads on this server are replication (and me trying to test this out).  There are no reads, all the DML is INSERT DELAYED.

concurrent_insert is 1

mysql> show global variables like 'myisam%';
+---------------------------+---------------------+
| Variable_name             | Value               |
+---------------------------+---------------------+
| myisam_data_pointer_size  | 6                   |
| myisam_max_sort_file_size | 9223372036853727232 |
| myisam_recover_options    | OFF                 |
| myisam_repair_threads     | 1                   |
| myisam_sort_buffer_size   | 8388608             |
| myisam_stats_method       | nulls_unequal       |
| myisam_use_mmap           | OFF                 |
+---------------------------+---------------------+
7 rows in set (0.01 sec)

I cannot post the schema nor a sample INSERT query as they involves sensitive data.

This is MySQL 5.1.41 on
Red Hat Enterprise Linux Server release 5.4 (Tikanga)
Kernel \r on an \m

Sheeri,

thank you for the feedback. Although would be good if you could provide schema/example query. Probably replacing field names and data with some dummy values will work?

Sheeri,

thank you for the feedback.

> This also appears on a large (over 15 million rows) MyISAM table after an INSERT DELAYED
is being run, it takes about 15 seconds to free the items. 

Is it only probelm on your side or is it additional detail for deadlock like in the initial report. Because single 15 seconds "freeing items" can be expected behavior which depends on machine capability and settings.

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".