3

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?

Improve this question
2
  • Can you add the output of \s and some iostat during a period when the update takes 3+seconds?
    – Derek Downey
    Commented Apr 2, 2013 at 14:56
  • @derek-downey Just added this information, see UPDATE 1
    – altmannmarcelo
    Commented Apr 2, 2013 at 16:02

1 Answer 1

Reset to default
3

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 lower innodb_max_dirty_pages_pct to 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.

Improve this answer
2
  • Thanks for your answer, I'll give it a try and post the feedback in here.
    – altmannmarcelo
    Commented Apr 3, 2013 at 8:28
  • I've been playing with innodb_max_dirty_pages_pct for last few days, it doesn't not solve the entire problem, some days during a busy IO activity, I still have some slow queries, but it decreased from 190 a day to ~5. thanks for your help.
    – altmannmarcelo
    Commented Apr 5, 2013 at 8:41

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.