Mysql – Queries getting stuck on very simple COUNT queries

innodbMySQLpercona-server

process list:

| 16004 | metrics | xxx:64616      | metrics | Query   | 29064 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356856200'                                        |         0 |             0 |      1021 |
| 16019 | metrics | xxx:23506      | metrics | Query   | 29043 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356856200'                                        |         0 |             0 |      1021 |
| 16102 | metrics | xxx:9117       | metrics | Query   | 28881 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356856200'                                        |         0 |             0 |      1021 |
| 16149 | metrics | xxx:14772      | metrics | Query   | 28768 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356856200'                                        |         0 |             0 |      1021 |
| 16384 | metrics | xxx:51572      | metrics | Query   | 27916 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356858000'                                        |         0 |             0 |      1021 |
...
| 17890 | metrics | xxx:28643      | metrics | Query   |   709 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356885000'                                        |         0 |             0 |        21 |
| 17924 | metrics | xxx:48797      | metrics | Query   |   681 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356885000'                                        |         0 |             0 |        21 |
| 17929 | metrics | xxx:55624      | metrics | Query   |   671 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356885000'                                        |         0 |             0 |        21 |
| 17938 | metrics | xxx:2632       | metrics | Query   |   654 | Sending data | SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356885000'                                        |         0 |             0 |        21 |

The table only has around 2500 rows, only ~1000 need to be scanned. Table is InnoDB.

This started happening last night. I was not able to run REPAIR TABLE but ANALYZE TABLE ran ok. I can't run any selects manually. When it happened last night I had to kill the mysql process and let it do crash recovery but it's doing it again.

UPDATEs on the table run without error (it is frequently updated), it just seems to be anything that selects from it that use COUNT(). I am able to SELECT * FROM Plugin and have every row returned, but even if I do SELECT COUNT(ID) FROM Plugin it still freezes on sending data

Explain:

mysql> explain SELECT COUNT(*) FROM Plugin where LastUpdated >= '1356856200';
+----+-------------+--------+-------+---------------+-------------+---------+------+------+--------------------------+
| id | select_type | table  | type  | possible_keys | key         | key_len | ref  | rows | Extra                    |
+----+-------------+--------+-------+---------------+-------------+---------+------+------+--------------------------+
|  1 | SIMPLE      | Plugin | range | LastUpdated   | LastUpdated | 5       | NULL | 1382 | Using where; Using index |

MySQL is using Percona Server 5.5.27

Any ideas on what is causing this?

Thanks a lot.

EDIT: innodb% variables and INNODB STATUS

Rolando: you say to increase innodb_io_capacity could you please explain? I am using 2x 7200 rpm hard drives in a ZFS mirror. Why should I increase it to 2000 ? The MySQL website advises 100 for single 7200 rpm drives (I have it at the default 200)

Excerpt from INNODB STATUS. These lovely selects have been stuck for half a day now. These are the oldest queries.

---TRANSACTION 27986E9D1, ACTIVE 48622 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 570263, OS thread handle 0xad7380000, query id 1217058950 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357635600'
Trx read view will not see trx with id >= 27986E9D3, sees < 278C78F08
---TRANSACTION 2797C7249, ACTIVE 49200 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 570063, OS thread handle 0xad7380800, query id 1216141959 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357635600'
Trx read view will not see trx with id >= 2797C724A, sees < 278C78F08

Full status:

=====================================
130109 22:44:19 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 50 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 737366 1_second, 728615 sleeps, 73673 10_second, 921 background, 911 flush
srv_master_thread log flush and writes: 766639
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 75724985, signal count 103543991
--Thread 46560449536 has waited at row0sel.c line 3941 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x83368d9b8 '&block->lock'
a writer (thread id 46560448512) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 942
Last time write locked in file /usr/local/src/Percona-Server-5.5.27-rel28.1/storage/innobase/row/row0upd.c line 2194
--Thread 46560428032 has waited at row0sel.c line 2924 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x8337b76f8 '&block->lock'
number of readers 1, waiters flag 0, lock_word: fffff
Last time read locked in file btr0sea.c line 942
Last time write locked in file /usr/local/src/Percona-Server-5.5.27-rel28.1/storage/innobase/row/row0upd.c line 2194
--Thread 46560448512 has waited at row0upd.c line 2194 for 0.0000 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x83368d9b8 '&block->lock'
a writer (thread id 46560448512) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 942
Last time write locked in file /usr/local/src/Percona-Server-5.5.27-rel28.1/storage/innobase/row/row0upd.c line 2194
--Thread 46560446464 has waited at row0sel.c line 2924 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x83368d9b8 '&block->lock'
a writer (thread id 46560448512) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 1, lock_word: ffffffffffffffff
Last time read locked in file btr0sea.c line 942
Last time write locked in file /usr/local/src/Percona-Server-5.5.27-rel28.1/storage/innobase/row/row0upd.c line 2194
Mutex spin waits 860007450, rounds 4788572135, OS waits 44460586
RW-shared spins 56868852, rounds 806806376, OS waits 12775136
RW-excl spins 115255109, rounds 878353038, OS waits 11254430
Spin rounds per wait: 5.57 mutex, 14.19 RW-shared, 7.62 RW-excl
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)
I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (read thread)
I/O thread 7 state: waiting for i/o request (read thread)
I/O thread 8 state: waiting for i/o request (read thread)
I/O thread 9 state: waiting for i/o request (read thread)
I/O thread 10 state: waiting for i/o request (write thread)
I/O thread 11 state: waiting for i/o request (write thread)
I/O thread 12 state: waiting for i/o request (write thread)
I/O thread 13 state: waiting for i/o request (write thread)
I/O thread 14 state: waiting for i/o request (write thread)
I/O thread 15 state: waiting for i/o request (write thread)
I/O thread 16 state: waiting for i/o request (write thread)
I/O thread 17 state: waiting for i/o request (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
6880197 OS file reads, 409935916 OS file writes, 1108361 OS fsyncs
1 pending preads, 1 pending pwrites
15.60 reads/s, 16930 avg bytes/read, 190.92 writes/s, 2.34 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 824, free list len 518, seg size 1343, 364193 merges
merged operations:
 insert 589402, delete mark 221097, delete 9349
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 21249841, node heap has 32061 buffer(s)
142440.39 hash searches/s, 8066.70 non-hash searches/s
---
LOG
---
Log sequence number 3642503658567
Log flushed up to   3642503574648
Last checkpoint at  3636441447521
Max checkpoint age    6957135914
Checkpoint age target 6739725417
Modified age          6062211046
Checkpoint age        6062211046
0 pending log writes, 0 pending chkp writes
398344529 log i/o's done, 170.86 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 11031019520; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 695290368       (169998728 + 525291640)
    Page hash           10625704 (buffer pool 0 only)
    Dictionary cache    42705560        (42501104 + 204456)
    File system         99832   (82672 + 17160)
    Lock system         26573920        (26563016 + 10904)
    Recovery system     0       (0 + 0)
Dictionary memory allocated 204456
Buffer pool size        655359
Buffer pool size, bytes 10737401856
Free buffers            96
Database pages          623202
Old database pages      230029
Modified db pages       307887
Pending reads 1
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 20888946, not young 0
183.06 youngs/s, 0.00 non-youngs/s
Pages read 6929404, created 2039787, written 15209639
16.10 reads/s, 11.04 creates/s, 23.24 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 12.42/s, Random read ahead 0.00/s
LRU len: 623202, unzip_LRU len: 0
I/O sum[750]:cur[6], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
20 read views open inside InnoDB
---OLDEST VIEW---
Normal read view
Read view low limit trx n:o 2797C724A
Read view up limit trx id 278C78F08
Read view low limit trx id 2797C724A
Read view individually stored trx ids:
Read view trx id 2797C7249
Read view trx id 2797C6206
Read view trx id 2797A2F63
Read view trx id 27976266E
Read view trx id 279761B1E
Read view trx id 278C78F08
-----------------
Main thread id 34397547520, state: sleeping
Number of rows inserted 42523215, updated 894466983, deleted 12775, read 9294801842
12.36 inserts/s, 907.78 updates/s, 0.00 deletes/s, 17273.29 reads/s
------------
TRANSACTIONS
------------
Trx id counter 27B056747
Purge done for trx's n:o < 278FA84BC undo n:o < 5D
History list length 15024237
LIST OF TRANSACTIONS FOR EACH SESSION:
[...]
---TRANSACTION 279D23E45, ACTIVE 42765 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 572264, OS thread handle 0xb0420f400, query id 1225918036 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357641000'
Trx read view will not see trx with id >= 279D23E48, sees < 2797C7249
---TRANSACTION 279B9A787, ACTIVE 45181 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 571429, OS thread handle 0xad737c400, query id 1222536287 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357639200'
Trx read view will not see trx with id >= 279B9A78D, sees < 2797C7249
---TRANSACTION 2799448B4, ACTIVE 47853 sec fetching rows
mysql tables in use 1, locked 0xxx.ip.xxx
MySQL thread id 570543, OS thread handle 0xadb3ea000, query id 1218229116 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357635600'
Trx read view will not see trx with id >= 2799448B5, sees < 278C78F08
---TRANSACTION 27986E9D1, ACTIVE 48622 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 570263, OS thread handle 0xad7380000, query id 1217058950 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357635600'
Trx read view will not see trx with id >= 27986E9D3, sees < 278C78F08
---TRANSACTION 2797C7249, ACTIVE 49200 sec fetching rows
mysql tables in use 1, locked 0
MySQL thread id 570063, OS thread handle 0xad7380800, query id 1216141959 lb1.xxxx xxx.ip.xxx metrics Sending data
SELECT COUNT(*) FROM Plugin where LastUpdated >= '1357635600'
Trx read view will not see trx with id >= 2797C724A, sees < 278C78F08
----------------------------
END OF INNODB MONITOR OUTPUT
============================

innodb% variables

| innodb_adaptive_flushing                  | OFF                    |
| innodb_adaptive_flushing_method           | estimate               |
| innodb_adaptive_hash_index                | ON                     |
| innodb_adaptive_hash_index_partitions     | 1                      |
| innodb_additional_mem_pool_size           | 10485760               |
| innodb_autoextend_increment               | 8                      |
| innodb_autoinc_lock_mode                  | 1                      |
| innodb_blocking_buffer_pool_restore       | OFF                    |
| innodb_buffer_pool_instances              | 1                      |
| innodb_buffer_pool_restore_at_startup     | 0                      |
| innodb_buffer_pool_shm_checksum           | ON                     |
| innodb_buffer_pool_shm_key                | 0                      |
| innodb_buffer_pool_size                   | 10737418240            |
| innodb_change_buffering                   | all                    |
| innodb_checkpoint_age_target              | 0                      |
| innodb_checksums                          | ON                     |
| innodb_commit_concurrency                 | 0                      |
| innodb_concurrency_tickets                | 500                    |
| innodb_corrupt_table_action               | assert                 |
| innodb_data_file_path                     | ibdata1:10M:autoextend |
| innodb_data_home_dir                      |                        |
| innodb_dict_size_limit                    | 0                      |
| innodb_doublewrite                        | OFF                    |
| innodb_doublewrite_file                   |                        |
| innodb_fake_changes                       | OFF                    |
| innodb_fast_checksum                      | OFF                    |
| innodb_fast_shutdown                      | 1                      |
| innodb_file_format                        | Barracuda              |
| innodb_file_format_check                  | ON                     |
| innodb_file_format_max                    | Antelope               |
| innodb_file_per_table                     | ON                     |
| innodb_flush_log_at_trx_commit            | 2                      |
| innodb_flush_method                       | O_DIRECT               |
| innodb_flush_neighbor_pages               | none                   |
| innodb_force_load_corrupted               | OFF                    |
| innodb_force_recovery                     | 0                      |
| innodb_ibuf_accel_rate                    | 100                    |
| innodb_ibuf_active_contract               | 1                      |
| innodb_ibuf_max_size                      | 5368692736             |
| innodb_import_table_from_xtrabackup       | 0                      |
| innodb_io_capacity                        | 200                    |
| innodb_kill_idle_transaction              | 0                      |
| innodb_large_prefix                       | OFF                    |
| innodb_lazy_drop_table                    | 0                      |
| innodb_lock_wait_timeout                  | 50                     |
| innodb_locks_unsafe_for_binlog            | OFF                    |
| innodb_log_block_size                     | 512                    |
| innodb_log_buffer_size                    | 8388608                |
| innodb_log_file_size                      | 4294967296             |
| innodb_log_files_in_group                 | 2                      |
| innodb_log_group_home_dir                 | ./                     |
| innodb_max_dirty_pages_pct                | 75                     |
| innodb_max_purge_lag                      | 0                      |
| innodb_merge_sort_block_size              | 1048576                |
| innodb_mirrored_log_groups                | 1                      |
| innodb_old_blocks_pct                     | 37                     |
| innodb_old_blocks_time                    | 0                      |
| innodb_open_files                         | 300                    |
| innodb_page_size                          | 16384                  |
| innodb_purge_batch_size                   | 20                     |
| innodb_purge_threads                      | 1                      |
| innodb_random_read_ahead                  | OFF                    |
| innodb_read_ahead                         | none                   |
| innodb_read_ahead_threshold               | 56                     |
| innodb_read_io_threads                    | 8                      |
| innodb_recovery_stats                     | OFF                    |
| innodb_recovery_update_relay_log          | OFF                    |
| innodb_replication_delay                  | 0                      |
| innodb_rollback_on_timeout                | OFF                    |
| innodb_rollback_segments                  | 128                    |
| innodb_show_locks_held                    | 10                     |
| innodb_show_verbose_locks                 | 0                      |
| innodb_spin_wait_delay                    | 6                      |
| innodb_stats_auto_update                  | 1                      |
| innodb_stats_method                       | nulls_equal            |
| innodb_stats_on_metadata                  | ON                     |
| innodb_stats_sample_pages                 | 8                      |
| innodb_stats_update_need_lock             | 1                      |
| innodb_strict_mode                        | OFF                    |
| innodb_support_xa                         | OFF                    |
| innodb_sync_spin_loops                    | 30                     |
| innodb_table_locks                        | ON                     |
| innodb_thread_concurrency                 | 0                      |
| innodb_thread_concurrency_timer_based     | OFF                    |
| innodb_thread_sleep_delay                 | 10000                  |
| innodb_use_global_flush_log_at_trx_commit | ON                     |
| innodb_use_native_aio                     | OFF                    |
| innodb_use_sys_malloc                     | ON                     |
| innodb_use_sys_stats_table                | OFF                    |
| innodb_version                            | 1.1.8-27.0             |
| innodb_write_io_threads                   | 8                      |xxxx

Best Answer

I know this is just a guess but here it goes...

I think your InnoDB is underconfigured. Please run the follolwing:

SHOW VARIABLES LIKE 'innodb%';

and post the output into the question.

Since you are using Percona Server, you must raise the following:

innodb_read_io_threads
- Default for MySQL is 4
- Default for Percona Server is 8
- Please raise it to the max value, 64
innodb_write_io_threads
- Default for MySQL is 4
- Default for Percona Server is 8
- Please raise it to the max value, 64
innodb_io_capacity (raise it to 2000 for starters)
innodb_thread_concurrency
- Default for MySQL 5.5 is 0
- Default for Percona Server is 0
- Default for MySQL 5.1 is 8
- Default for MySQL 5.0 is 8
- Since you are using Percona Server 5.5, leave it at zero ( 0 )

Concerning the counts being held up, please take into consideration the MVCC that is going on. Each individual connection running a SELECT query is monitoring what the count was before any attempted UPDATEs. UPDATE queries may perform page locks in the Clustered Index. This could easily hold up SELECT queries that pass through the PRIMARY KEY. Even though the secondary index LastUpdated is being used, each secondary key entry has the Clustered Key entry right along with it. Therefore, the PRIMARY KEY may be accessed as a point of reference and it taking a backseat to UPDATEs. You should be able to see this back logging in SHOW ENGINE INNODB STATUS\G. This may explain slow counts.

This may still occur even if you raise the values I just mentioned given enough UPDATE traffic.

SUGGESTIONS

You probably need to tune your queries so they do not request so much data.
You should also avoid doing mysqldumps in the middle of the business day and this tends to load every data page and its grandmother into the Buffer Pool, only to have those pages quietly evicted. If you have to run mysqldumps, setup a MySQL Slave and o your dump from the Slave.
You could experiment with disabling the change buffering (set innodb_change_buffering to 0).

UPDATE 2014-08-11 16:45 EDT

Please look back at the comment section. Derek Downey gave you a link to my 3 year old post. Based on the 2012 update in my post, you need to set innodb_buffer_pool_instances = 2. This will help curb mysqld's swap behavior.

From your SHOW ENGINE INNODB STATUS\G, you have too few read and write threads

--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)

You only have 4 read and 4 write I/O threads. Bump up your threads

innodb_read_io_threads = 16
innodb_write_io_threads = 16

If you had more that 2 cores, I would use 32 or 64. You can try 16 for now.

InnoDB is always at odds with the Query Cache. Please disable it.

query_cache_size = 0

You need a bigger log buffer for better InnoDB write performance

innodb_log_buffer_size = 256M

These are all the changes

[mysqld]
innodb_buffer_pool_instances = 2
innodb_log_buffer_size = 256M
innodb_read_io_threads = 16
innodb_write_io_threads = 16
query_cache_size = 0

Best Answer

Related Solutions

Mysql – How to decipher the transaction message in innodb status log.

MySQL buffer pool usage + high load

SUGGESTIONS

UPDATE 2014-08-11 16:45 EDT

Related Question