Mysql – Frequently slow queries while in the ‘Update’ state

innodbMySQLperformancereplication

I have two tables that I update very frequently, one with a direct UPDATE .. and another INSERT .. ON DUPLICATE KEY UPDATE ... Normally these queries are instant but at times will take 0.1s to 1+ seconds and then be instant again for a few seconds.

Another thing to note, I have two MySQL servers (in the same private network). All select queries (barring one or two) are executed on the slave and the inserts seen here are of course on the master. The slowdowns are most apparent when the database is under a large load. Lastly, I am using xtradb (to see if it helped) but the same behaviour occurred while on just plain MySQL 5.5 InnoDB.

-- CustomData
+-----------+---------+------+-----+---------+-------+
| Field     | Type    | Null | Key | Default | Extra |
+-----------+---------+------+-----+---------+-------+
| Server    | int(11) | NO   | PRI | NULL    |       |
| Plugin    | int(11) | NO   | PRI | NULL    |       |
| ColumnID  | int(11) | NO   | PRI | NULL    |       |
| DataPoint | int(11) | NO   |     | NULL    |       |
| Updated   | int(11) | NO   | MUL | NULL    |       |
+-----------+---------+------+-----+---------+-------+

Ex. of a couple queries:

mysql> insert into CustomData (Server, Plugin, ColumnID, DataPoint, Updated) VALUES ( 52707, 1, 1, 0, 1327093596) on duplicate key update DataPoint = 0 , Updated = 1327093596 ;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into CustomData (Server, Plugin, ColumnID, DataPoint, Updated) VALUES ( 52707, 1, 1, 0, 1327093596) on duplicate key update DataPoint = 0 , Updated = 1327093596 ;
Query OK, 0 rows affected (0.12 sec)

mysql> insert into CustomData (Server, Plugin, ColumnID, DataPoint, Updated) VALUES ( 52707, 1, 1, 0, 1327093596) on duplicate key update DataPoint = 0 , Updated = 1327093596 ;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into CustomData (Server, Plugin, ColumnID, DataPoint, Updated) VALUES ( 52707, 1, 1, 0, 1327093596) on duplicate key update DataPoint = 0 , Updated = 1327093596 ;
Query OK, 0 rows affected (0.00 sec)

EXPLAIN-

mysql> explain select * from CustomData where Server = 52707 and Plugin = 1 and ColumnID = 1 ;
+----+-------------+------------+-------+---------------+---------+---------+-------------------+------+-------+
| id | select_type | table      | type  | possible_keys | key     | key_len | ref               | rows | Extra |
+----+-------------+------------+-------+---------------+---------+---------+-------------------+------+-------+
|  1 | SIMPLE      | CustomData | const | PRIMARY,Cron  | PRIMARY | 12      | const,const,const |    1 |       |
+----+-------------+------------+-------+---------------+---------+---------+-------------------+------+-------+

Profiler (for the 0.12 sec query)

mysql> show profile for query 56 ;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.000062 |
| checking permissions | 0.000005 |
| Opening tables       | 0.000016 |
| System lock          | 0.000007 |
| init                 | 0.000011 |
| update               | 0.129531 |
| end                  | 0.000005 |
| query end            | 0.000012 |
| closing tables       | 0.000008 |
| freeing items        | 0.000017 |
| logging slow query   | 0.000001 |
| cleaning up          | 0.000036 |
+----------------------+----------+

All other problematic queries are very similar. I don't notice any long-running queries in show processlist;

SHOW ENGINE INNODB STATUS (need 10 rep to post >2 links, so)-
pastebin .com/raw.php?i=tdtZeTCJ

One last thing I would like to note, that in the given example, any worker only ever executes an INSERT .. ON DUPLICATE KEY on a unique row, not the same row (so each query is for a different row)

Thanks in advance!

EDIT:

All of my data is around 3G with indexes. Buffer pool size was 2G at first but have tried 4G as well.

my.cnf-

[mysqld]
datadir = /data/mysql
socket = /var/run/mysqld/mysqld.sock
user = mysql
bind-address = 10.10.1.7

log-slow-queries = mysql-slow.log
long_query_time = 5
log-queries-not-using-indexes

# Replication
server-id        = 1

# master
log-bin          = /var/log/mysql/mysql-bin.log
expire-logs-days = 10
binlog-do-db     = metrics
max_binlog_size  = 104857600
binlog_format    = MIXED

# slave
# replicate-do-db  = metrics
# read_only        = 1

# /Replication

skip-external-locking
sysdate-is-now

performance_schema

log-error=/var/log/mysql.log

default-storage-engine          = InnoDB

innodb_file_per_table           = 1
innodb_file_format              = barracuda

innodb_buffer_pool_size          = 4G
innodb_additional_mem_pool_size  = 10M
innodb_log_buffer_size           = 8M
innodb_flush_log_at_trx_commit   = 0
innodb_lock_wait_timeout         = 50
innodb_fast_shutdown             = 1
innodb_flush_method              = O_DIRECT
transaction_isolation            = READ-COMMITTED

max_connections                 = 4092
connect_timeout                 = 86400
wait_timeout                    = 86400
interactive_timeout             = 86400
max_allowed_packet              = 64M

open_files_limit                = 2048
table_cache                     = 2048
net_buffer_length               = 8K
query_cache_type                = 1
query_cache_size                = 16M
thread_cache                    = 100
thread_stack                    = 512K
tmpdir                          = /dev/shm
tmp_table_size                  = 64M

key_buffer_size                 = 64M
sort_buffer_size                = 512K
net_buffer_length               = 8K
read_buffer_size                = 256K
read_rnd_buffer_size            = 512K
myisam_sort_buffer_size         = 8M

[mysqldump]
quick
max_allowed_packet              = 16M
[mysql]
no-auto-rehash

[myisamchk]
key_buffer_size                 = 20M
sort_buffer_size                = 20M
read_buffer                     = 2M
write_buffer                    = 2M

[mysqlhotcopy]
interactive-timeout

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

EDIT2

innotop-

one two

I read about gap locking – is it possible that it is gap locking my Plugin and ColumnID columns, ignoring the fact that the PK is 3 cols and also the fact that I am using READ-COMMITTED so it shouldn't be anyway ? As can be seen in innotop, some are these are very close so if this is the case then there will be a lot of locks going around

mysql> show indexes from CustomData;
+------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table      | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| CustomData |          0 | PRIMARY  |            1 | Server      | A         |     1073724 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          0 | PRIMARY  |            2 | Plugin      | A         |     1879017 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          0 | PRIMARY  |            3 | ColumnID    | A         |     7516069 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          1 | Cron     |            1 | Plugin      | A         |          20 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          1 | Cron     |            2 | ColumnID    | A         |          20 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          1 | Cron     |            3 | Updated     | A         |     7516069 |     NULL | NULL   |      | BTREE      |         |               |
| CustomData |          1 | Updated  |            1 | Updated     | A         |     2505356 |     NULL | NULL   |      | BTREE      |         |               |
+------------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+

The cron key is only used every 30 minutes and is not even enabled right now (incase it was brought up)

Best Answer

You need to make some adjustments in your InnoDB setup

ADJUSTMENT #1 : Bigger InnoDB Redo Logs

Since I I do not see innodb_log_file_size, I assume you have the default of 5M. Since your innodb_buffer_pool_size = is 4G, you need 1G redo logs.

ADJUSTMENT #2 : Have InnoDB uses all CPUs

Out of the box, InnoDB does not use all CPUs. I wrote a post long ago about how InnoDB LEFT UNCONFIGURED may work faster in older versions. I also wrote posts about multicore engagement for InnoDB:

With these things said, here are the adjustments to make

cp /etc/my.cnf /etc/my.cnf_old

Add this setting to /etc/my.cnf

[mysqld]
innodb_log_file_size = 1G
innodb_io_capacity = 20000
innodb_read_io_threads = 5000
innodb_write_io_threads = 5000

Next, run these steps

service mysql stop
mv /var/log/mysql/ib_logfile0 /var/log/mysql/ib_logfile0_old 
mv /var/log/mysql/ib_logfile1 /var/log/mysql/ib_logfile1_old
service mysql start

Now, all cores with assist InnoDB and there is much more room for transaction isolation

Give it a Try !!!