Mysql – InnoDB – High disk write I/O on ibdata1 file and ib_logfile0

innodbMySQL

Server Specification: VPS with following info

model name  : Intel(R) Xeon(R) CPU           E5649  @ 2.53GHz
MemTotal:      2058776 kB
MemFree:        244436 kB

We are running IP.Board from Invision Power Services, we are using
innodb_file_per_table and have reloaded the database to reduce ibdata1 size. However, we still got problem of high CPU and I/O usage lately despite of the reduced ibdata1 size.

From my inspection, I believe that it causes by high I/O usage on ibdata1. Below is the data I obtained using pt-ioprofile -cell sizes (in Percona ToolKit). Basically, it's the total I/O amount collected in the period of 30 seconds.

# pt-ioprofile -cell sizes
Fri Jul 20 10:22:23 ICT 2012
Tracing process ID 8581
     total      pread       read     pwrite      fsync       open      close   getdents      lseek      fcntl filename
   6995968          0          0    6995968          0          0          0          0          0          0 /db/mysql/ibdata1
   1019904          0          0    1019904          0          0          0          0          0          0 /db/mysql/ib_logfile0
    204800     204800          0          0          0          0          0          0          0          0 /db/mysql/admin_phpbb3forum/phpbb_posts.ibd
     49152      49152          0          0          0          0          0          0          0          0 /db/mysql/admin_ips/ips_reputation_cache.ibd
     32768      32768          0          0          0          0          0          0          0          0 /db/mysql/admin_ips/ips_reputation_totals.ibd
     29808          0          0          0          0          0          0      29808          0          0 /db/mysql/admin_ips/
... (other trivial I/O records truncated)

Running iotop and I see DISK WRITE: goes up and down around 2M/s and 200K/s

My question is, why we have high I/O write on ibdata1 and ib_logfileX while we have only about 5-10 small update per second into our sessions tables, which are also MEMORY table (only about 300K in size)? It is puzzling me because there's also no equivalent write I/O on any other table file, which indicates that the write I/O is not caused by UPDATE/INSERT/DELETE.

Note that I'm only a programmer who are just by chance have the duty to maintain this, so please feel free to ask for more info. I've done a lot of things to this server, but please don't assume that I have done anything I should have done already.

Additional info:

# ls -l /db/mysql/ib*
-rw-rw---- 1 mysql mysql  18874368 Jul 21 01:26 /db/mysql/ibdata1
-rw-rw---- 1 mysql mysql 134217728 Jul 21 01:26 /db/mysql/ib_logfile0
-rw-rw---- 1 mysql mysql 134217728 Jul 21 01:26 /db/mysql/ib_logfile1

and

mysql> SHOW VARIABLES LIKE 'innodb%';
+-------------------------------------------+------------------------+
| Variable_name                             | Value                  |
+-------------------------------------------+------------------------+
| innodb_adaptive_flushing                  | ON                     |
| innodb_adaptive_flushing_method           | estimate               |
| innodb_adaptive_hash_index                | ON                     |
| innodb_adaptive_hash_index_partitions     | 1                      |
| innodb_additional_mem_pool_size           | 20971520               |
| 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                   | 402653184              |
| 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                        | ON                     |
| 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                    | Barracuda              |
| innodb_file_per_table                     | ON                     |
| innodb_flush_log_at_trx_commit            | 2                      |
| innodb_flush_method                       | O_DIRECT               |
| innodb_flush_neighbor_pages               | 0                      |
| innodb_force_load_corrupted               | OFF                    |
| innodb_force_recovery                     | 0                      |
| innodb_ibuf_accel_rate                    | 100                    |
| innodb_ibuf_active_contract               | 1                      |
| innodb_ibuf_max_size                      | 201310208              |
| innodb_import_table_from_xtrabackup       | 0                      |
| innodb_io_capacity                        | 4000                   |
| 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                     | 4096                   |
| innodb_log_buffer_size                    | 4194304                |
| innodb_log_file_size                      | 134217728              |
| innodb_log_files_in_group                 | 2                      |
| innodb_log_group_home_dir                 | ./                     |
| innodb_max_dirty_pages_pct                | 75                     |
| innodb_max_purge_lag                      | 0                      |
| 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                         | linear                 |
| innodb_read_ahead_threshold               | 56                     |
| innodb_read_io_threads                    | 24                     |
| 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                  | 0                      |
| innodb_stats_method                       | nulls_equal            |
| innodb_stats_on_metadata                  | OFF                    |
| innodb_stats_sample_pages                 | 8                      |
| innodb_stats_update_need_lock             | 1                      |
| innodb_strict_mode                        | OFF                    |
| innodb_support_xa                         | ON                     |
| 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                     | ON                     |
| innodb_use_sys_malloc                     | ON                     |
| innodb_use_sys_stats_table                | OFF                    |
| innodb_version                            | 1.1.8-rel27.1          |
| innodb_write_io_threads                   | 24                     |
+-------------------------------------------+------------------------+
90 rows in set (0.00 sec)

From @RolandoMySQLDBA : Please run this

SET @TimeInterval = 300;
SELECT variable_value INTO @num1 FROM information_schema.global_status
WHERE variable_name = 'Innodb_os_log_written';
SELECT SLEEP(@TimeInterval);
SELECT variable_value INTO @num2 FROM information_schema.global_status
WHERE variable_name = 'Innodb_os_log_written';
SET @ByteWrittenToLog = @num2 - @num1;
SET @KB_WL = @ByteWrittenToLog / POWER(1024,1) * 3600 / @TimeInterval;
SET @MB_WL = @ByteWrittenToLog / POWER(1024,2) * 3600 / @TimeInterval;
SET @GB_WL = @ByteWrittenToLog / POWER(1024,3) * 3600 / @TimeInterval;
SELECT @KB_WL,@MB_WL,@GB_WL;

and show the output. This will tell you how many bytes per hour is written to ib_logfile0/ib_logfile1 based on the next 5 minutes.

Above SQL query result (At 8am local time, while the members online is about 25% of the stat during the day):

mysql> SELECT @KB_WL,@MB_WL,@GB_WL;
+--------+----------+-------------------+
| @KB_WL | @MB_WL   | @GB_WL            |
+--------+----------+-------------------+
|  95328 | 93.09375 | 0.090911865234375 |
+--------+----------+-------------------+
1 row in set (0.00 sec)

Best Answer

Here are a few things you could change

innodb_log_buffer_size : You have 4M. The default is 8M. Try raising it to 8M.
innodb_log_file_size : You have 128M. Given the following info you supplied
- you write on avg 93MB per hour to the innodb log files, based on 25% of the stat
- peak time would be about 372 MB an hour
- half is 186 MB round off to 192MB
- set innodb_log_file_size to 192M
innodb_io_capacity seems a little high, make it 200 or 300 (depending on hardware)
innodb_read_io_threads and innodb_write_io_threads should be maxed out at 64. Sometimes, less is better in a write-heavy environment. Use 8 or 16 in such cases.

To change innodb_log_file_size to 192M, add this to /etc/my.cnf

[mysqld]
innodb_log_buffer_size=8M
innodb_log_file_size=192M
innodb_open_files=300
innodb_read_io_threads=64
innodb_write_io_threads=64

then do the following

mysql -u... -p... -e"FLUSH TABLES;"
service mysql stop
mv /var/lib/mysql/ib_logfile0 /var/lib/mysql/ib_logfile0000
mv /var/lib/mysql/ib_logfile1 /var/lib/mysql/ib_logfile0001
service mysql start

Test this during slow times and see if this improves things

UPDATE 2012-10-19 12:31 EDT

To put your situation into perspective think about what the purposes of ibdata1 and ib_logfile0/1 are. Rather than rewriting everything, please read my most recent post about ibdata1 and InnoDB Log Files : What exactly are iblog files in mysql

Once you have read my other post, now consider this: What would increase I/O on these files?

Updating Secondary Indexes in ibdata1's Insert Buffer
Cleaning up the Rollback Segments/Undo Space

IMHO I would increase the InnoDB Buffer Pool from 384M to 1G.

I would also recommend upgrading RAM to 8G

Related Solutions

InnoDB INSERT Performance Capabilities in MySQL

You need to tune your InnoDB settings in the following areas:

Make InnoDB access all your cores
Increase innodb_buffer_pool_size to 12G
Increase innodb_buffer_pool_instances to 2 (First run numactl --hardware to determine the number of Physical CPUs. What every number of CPUs it reports, use that number. I learned this recently in Jeremy Cole's Blog)
Increase Log File Size (innodb_log_file_size) to 2047M
support separate tablespace files for individual InnoDB tables (enaled innodb_file_per_table)
support either high performance or high durability (ACID Compliance)
- High Performance : innodb_flush_log_at_trx_commit set to 0 or 2
- High Durability : innodb_flush_log_at_trx_commit set to 1 (Default)
- Increase Size up the innodb_log_buffer_size in conjunction with the number of transactions per second (perhaps 32M)
- Your current setting for innodb_flush_log_at_trx_commit is good
- Your current setting for innodb_flush_method is good
Increase innodb_read_io_threads to 64
Increase innodb_write_io_threads to 64
Increase innodb_io_capactity to 10000

Here are my past posts on tuning the InnoDB storage engine

Is the CPU performance relevant for a database server? (Apr 26, 2012)
Why does InnoDB store all databases in one file? (Mar 25, 2012)
Multi cores and MySQL Performance (Sep 20, 2011)
Possible to make MySQL use more than one core? (Sep 12, 2011)
About single threaded versus multithreaded databases performance (May 26, 2011)
How to safely change MySQL innodb variable 'innodb_log_file_size'? (Feb 16, 2011)
How do you tune MySQL for a heavy InnoDB workload? (Feb 12, 2011)
Howto: Clean a mysql InnoDB storage engine? (October 29, 2010)

Mysql – Cannot write to thesql database while select query in process

Your first query is asking for 20,000 rows. what is being victimized here ???

Your Innodb Buffer Pool and Log Files.

Because of SELECT * FROM history WHERE log LIKE '%a%' ORDER BY log ASC LIMIT 0, 20000;, all the data pages for the history table is hogging InnoDB resources.

Since you are using Amazon RDS, you cannot resize the InnoDB Log Files. They are always 128M under all RDS MySQL models. Your buffer pool may or may not be full (You have 5882511360 set for it, which is 5610M or 5.4785G). Naturally, bigger model means more IOPs.

You can run this to see how full the buffer pool is

SELECT FORMAT(A.num * 100.0 / B.num,2) BufferPoolFullPct FROM
(SELECT variable_value num FROM information_schema.global_status
WHERE variable_name = 'Innodb_buffer_pool_pages_data') A,
(SELECT variable_value num FROM information_schema.global_status
WHERE variable_name = 'Innodb_buffer_pool_pages_total') B;

Another aspect I see is the log field (TEXT). You are asking for an ORDER BY on this big column.

You need to change the first query to throttle the SELECT. In other words, fetch smaller chunks of history.

If you cannot change the data or the query, there is nothing you can configure except to shift to m1.xlarge (Comes with 11922309120 as the Buffer Pool Size = 11370M = 11.1035G) although log file size would still be stuck at 128M.

Infrastructure aside, it is possible for SELECTs to block INSERTs, UPDATEs, and DELETEs in InnoDB.

I wrote about this before

Best Answer

UPDATE 2012-10-19 12:31 EDT

Related Solutions

InnoDB INSERT Performance Capabilities in MySQL

Mysql – Cannot write to thesql database while select query in process

Related Question