a few days ago we converted some write intensive tables from MyISAM to InnoDB hoping to have a better performance due the better locking system of InnoDB, but instead of gain performance, we start to see simple queries on slow log.
for exemple, the bellow query took 3.6 sec to run:
# Time: 130402 7:24:07
# User@Host: iron[iron] @ localhost []
# Query_time: 3.596235 Lock_time: 0.000033 Rows_sent: 0 Rows_examined: 1
SET timestamp=1364883847;
UPDATE `cookies` SET `lastSelectedLanguage`="english" WHERE `cookieID`="27276286";
see bellow the table structure:
mysql> describe cookies;
+----------------------+------------------+------+-----+---------+----------------+
| Field | Type | Null | Key | Default | Extra |
+----------------------+------------------+------+-----+---------+----------------+
| cookieID | bigint(20) | NO | PRI | NULL | auto_increment |
| containerID | int(10) unsigned | NO | MUL | NULL | |
| dtCreated | datetime | NO | | NULL | |
| lastSelectedLanguage | varchar(31) | YES | | NULL | |
+----------------------+------------------+------+-----+---------+----------------+
to run a select(not using cache) with the same WHERE clause it run in 0 sec
mysql> SELECT SQL_NO_CACHE * FROM `cookies` WHERE `cookieID`="27276286";
+----------+-------------+---------------------+----------------------+
| cookieID | containerID | dtCreated | lastSelectedLanguage |
+----------+-------------+---------------------+----------------------+
| 27276286 | 6 | 2013-04-02 06:23:52 | english |
+----------+-------------+---------------------+----------------------+
1 row in set (0.00 sec)
The server is a 16 core cpu's:
...
processor : 15
vendor_id : GenuineIntel
cpu family : 6
model : 44
model name : Intel(R) Xeon(R) CPU E5620 @ 2.40GHz
stepping : 2
cpu MHz : 2393.931
cache size : 12288 KB
...
And has SSD Drivers.
The total size of InnoDB tables on the server is 1.79 GB:
mysql> SELECT (SUM(DATA_LENGTH)+SUM(INDEX_LENGTH)) /1024/1024/1024 AS Total_InnoDB_in_GB FROM INFORMATION_SCHEMA.TABLES WHERE ENGINE='InnoDB';
+--------------------+
| Total_InnoDB_in_GB |
+--------------------+
| 1.781707763672 |
+--------------------+
1 row in set (0.12 sec)
As you can see bellow, we have 2.5 GB of innodb_buffer_pool_size witch is almost 1GB more the the sum of index + data
mysql> SHOW VARIABLES LIKE '%innodb%';
+-----------------------------------------+------------------------+
| Variable_name | Value |
+-----------------------------------------+------------------------+
| have_innodb | YES |
| ignore_builtin_innodb | OFF |
| innodb_adaptive_hash_index | ON |
| innodb_additional_mem_pool_size | 1048576 |
| innodb_autoextend_increment | 8 |
| innodb_autoinc_lock_mode | 1 |
| innodb_buffer_pool_size | 2684354560 |
| innodb_checksums | ON |
| innodb_commit_concurrency | 0 |
| innodb_concurrency_tickets | 500 |
| innodb_data_file_path | ibdata1:10M:autoextend |
| innodb_data_home_dir | |
| innodb_doublewrite | ON |
| innodb_fast_shutdown | 1 |
| innodb_file_io_threads | 4 |
| innodb_file_per_table | ON |
| innodb_flush_log_at_trx_commit | 2 |
| innodb_flush_method | O_DIRECT |
| innodb_force_recovery | 0 |
| innodb_lock_wait_timeout | 50 |
| innodb_locks_unsafe_for_binlog | OFF |
| innodb_log_buffer_size | 8388608 |
| innodb_log_file_size | 536870912 |
| innodb_log_files_in_group | 2 |
| innodb_log_group_home_dir | ./ |
| innodb_max_dirty_pages_pct | 90 |
| innodb_max_purge_lag | 0 |
| innodb_mirrored_log_groups | 1 |
| innodb_open_files | 300 |
| innodb_rollback_on_timeout | OFF |
| innodb_stats_method | nulls_equal |
| innodb_stats_on_metadata | ON |
| innodb_support_xa | ON |
| innodb_sync_spin_loops | 20 |
| innodb_table_locks | ON |
| innodb_thread_concurrency | 8 |
| innodb_thread_sleep_delay | 10000 |
| innodb_use_legacy_cardinality_algorithm | ON |
+-----------------------------------------+------------------------+
38 rows in set (0.00 sec)
I'm running version 5.1.66 (as the version 5.1 is the latest version included on non back-port repository of debian squeeze, update to 5.5/5.6 unfortunately is not an option)
mysql> SHOW VARIABLES LIKE 'version%';
+-------------------------+-----------------------+
| Variable_name | Value |
+-------------------------+-----------------------+
| version | 5.1.66-0+squeeze1-log |
| version_comment | (Debian) |
| version_compile_machine | x86_64 |
| version_compile_os | debian-linux-gnu |
+-------------------------+-----------------------+
4 rows in set (0.00 sec)
Update 1:
Just had a new occur on 16:46:02, see bellow the iostat from 14:46:00 (2 sec interval)
Tue Apr 2 16:46:00 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.88 1667.89 1369.53 801352236 658003944
Tue Apr 2 16:46:02 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.88 1667.91 1369.53 801366876 658004640
Tue Apr 2 16:46:04 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.89 1667.95 1369.52 801389476 658005912
Tue Apr 2 16:46:06 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.89 1667.95 1369.53 801389628 658012616
Tue Apr 2 16:46:08 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.89 1667.94 1369.53 801389652 658014192
Tue Apr 2 16:46:10 IST 2013
Linux 2.6.32-5-amd64 (hemlock) 02/04/13 _x86_64_ (16 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
2.54 0.00 0.44 0.22 0.00 96.79
Device: tps Blk_read/s Blk_wrtn/s Blk_read Blk_wrtn
sda 67.89 1667.93 1369.53 801389668 658015880
And also the \s in that period (16:46:00 16:46:02 16:46:04 16:46:06):
Tue Apr 2 16:46:00 IST 2013
--------------
mysql Ver 14.14 Distrib 5.1.66, for debian-linux-gnu (x86_64) using readline 6.1
Connection id: 370306
Current database:
Current user: readonly@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.1.66-0+squeeze1-log (Debian)
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: latin1
Conn. characterset: latin1
UNIX socket: /var/run/mysqld/mysqld.sock
Uptime: 9 hours 13 min 25 sec
Threads: 2 Questions: 5265901 Slow queries: 109 Opens: 9852 Flush tables: 1 Open tables: 2048 Queries per second avg: 158.587
--------------
Tue Apr 2 16:46:02 IST 2013
--------------
mysql Ver 14.14 Distrib 5.1.66, for debian-linux-gnu (x86_64) using readline 6.1
Connection id: 370336
Current database:
Current user: readonly@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.1.66-0+squeeze1-log (Debian)
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: latin1
Conn. characterset: latin1
UNIX socket: /var/run/mysqld/mysqld.sock
Uptime: 9 hours 13 min 27 sec
Threads: 11 Questions: 5266200 Slow queries: 109 Opens: 9853 Flush tables: 1 Open tables: 2048 Queries per second avg: 158.587
--------------
Tue Apr 2 16:46:04 IST 2013
--------------
mysql Ver 14.14 Distrib 5.1.66, for debian-linux-gnu (x86_64) using readline 6.1
Connection id: 370361
Current database:
Current user: readonly@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.1.66-0+squeeze1-log (Debian)
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: latin1
Conn. characterset: latin1
UNIX socket: /var/run/mysqld/mysqld.sock
Uptime: 9 hours 13 min 29 sec
Threads: 27 Questions: 5266361 Slow queries: 110 Opens: 9858 Flush tables: 1 Open tables: 2048 Queries per second avg: 158.582
--------------
Tue Apr 2 16:46:06 IST 2013
--------------
mysql Ver 14.14 Distrib 5.1.66, for debian-linux-gnu (x86_64) using readline 6.1
Connection id: 370402
Current database:
Current user: readonly@localhost
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server version: 5.1.66-0+squeeze1-log (Debian)
Protocol version: 10
Connection: Localhost via UNIX socket
Server characterset: latin1
Db characterset: latin1
Client characterset: latin1
Conn. characterset: latin1
UNIX socket: /var/run/mysqld/mysqld.sock
Uptime: 9 hours 13 min 31 sec
Threads: 2 Questions: 5267006 Slow queries: 117 Opens: 9864 Flush tables: 1 Open tables: 2048 Queries per second avg: 158.592
--------------
Does anyone has any clue about why this updates (it happens to insert and also to delete) are so slow?
Best Answer
I suspect your slow UPDATES occur due to your high
innodb_max_dirty_pages_pct. This is a very good article on how InnoDB handles checkpoints and dirty page flushing, but the gist of my recommendation is to lowerinnodb_max_dirty_pages_pctto 60 or 70 and see if that helps.Unfortunately, I suspect you are running native InnoDB in 5.1 and not the InnoDB plugin. This will limit your ability to tune your checkpoints.