Mysql – What causes InnoDB to write 100% more pages while slowing down answering queries

database-tuninginnodbMySQLperformance

I have a somewhat big database server: 4 processors, 32 cores, 288GB RAM, 2 ethernet cards bounded together, 2 independent RAID controller cards with 1GB cache each, 24 2.5" disks, being 8 SAS, 15KRPM, in the data partition in RAID10, and 3 SSD, in the Journal partition in RAID5, and 2 SAS, 15KRPM in RAID 1 for the operating system. The data partition has it's own RAID controller, and the O.S. and Journal share the other card.

I'm running Ubuntu 12.04.1 LTS and MySQL 5.1.56 with InnoDB plugin 12.7 from Percona on top of that.

To the Data Partition MySQL writes indexes and data files; to the Journal partition it writes binary logs, slow and error logs, and innodb journal files.

In the last few weeks I've been observing some weird behaviour: MySQL slows down answering to queries, and at the same time doubles the "InnoDB Buffer Pool Pages Written" metric. At the same time, I see InnoDB Log buffer filling up 5 times the usual levels for the usual workload. Also, I don't observe any mutex and lock granting activity changes on the graph.

This is my current configuration:

  basedir=/usr/
  datadir=/var/lib/mysql/data
  tmpdir=/var/lib/mysql/tmp
  server-id=1
  socket=/var/run/mysqld/mysqld.sock
  port=3306
  user=mysql
  pid-file=/var/run/mysqld/mysqld.pid
  language=/usr/share/mysql/english
  default-storage-engine=InnoDB
  read_only
  max_heap_table_size=256M
  tmp_table_size=256M
  table_cache=1024
  thread_cache_size=64
  thread_stack=1024K
  max_allowed_packet=16M
  max_connections=255
  max_user_connections=250
  skip-external-locking
  skip-slave-start
  master-info-file=/var/lib/mysql/relay/master.info
  relay-log=/var/lib/mysql/relay/relay-bin
  relay-log-index=/var/lib/mysql/relay/relay-bin.index
  relay-log-info-file=/var/lib/mysql/relay/relay-log.info
  log-slave-updates=1
  expire_logs_days=1
  sync_binlog=1
  max_binlog_size=1G
  binlog-format=MIXED
  log-bin=/var/lib/mysql/binary/mysqld-binlog
  log-bin-index=/var/lib/mysql/binary/mysqld-binlog.index
  log-warnings=2
  log-error=/var/lib/mysql/mysqld-err.log
  slow-query-log
  log_slow_slave_statements=1
  log_slow_timestamp_every=1
  slow_query_log_microseconds_timestamp=1
  log_slow_verbosity=full
  long-query-time=0.05
  slow-query-log-file=/var/lib/mysql/mysqld-slow.log
  innodb_adaptive_flushing=1
  innodb_additional_mem_pool_size=20M
  innodb_buffer_pool_size=16G
  innodb_data_file_path=ibdata1:20M:autoextend
  innodb_data_home_dir=/var/lib/mysql/data
  innodb_doublewrite_file=/var/lib/mysql/journal/ib_doublewrite
  innodb_fast_shutdown=0
  innodb_file_per_table
  innodb_flush_log_at_trx_commit=1
  innodb_flush_method=O_DIRECT
  innodb_io_capacity=1500
  innodb_log_group_home_dir=/var/lib/mysql/journal/
  innodb_max_dirty_pages_pct=75
  innodb_open_files=1024
  innodb_rollback_on_timeout
  innodb_thread_concurrency=20
  query_cache_size=0
  query_cache_type=0
  key-buffer-size=200M
  server-id=233111
  sql-mode=NO_AUTO_CREATE_USER
  max_connections=850
  max_user_connections=800
  read-only
  table-open-cache=1300
  log-error=/var/lib/mysql/log/dbserver-err.log
  slow-query-log-file=/var/lib/mysql/log/dbserver-slow.log
  relay-log=/var/lib/mysql/relay/dbserver-relay-bin
  relay-log-index=/var/lib/mysql/relay/dbserver-relay-bin.index
  relay-log-info-file=/var/lib/mysql/relay/dbserver-relay-log.info
  log-bin=/var/lib/mysql/binary/dbserver-mysqld-binlog
  log-bin-index=/var/lib/mysql/binary/dbserver-mysqld-binlog.index
  relay_log_purge=0
  innodb_buffer_pool_size=240G
  innodb_log_buffer_size=2G
  innodb_log_file_size=4G
  large-pages

And this is my current filesystem organization:

  SSD RAID5, Controller #0
  /var/lib/mysql/journal -> /srv/mysql/ssd/journal
  /var/lib/mysql/log     -> /srv/mysql/ssd/log
  /var/lib/mysql/relay   -> /srv/mysql/ssd/relay
  /var/lib/mysql/tmp     -> /srv/mysql/ssd/tmp

  SAS RAID 10, Controller #1
  /var/lib/mysql/backup  -> /srv/mysql/sas/backup
  /var/lib/mysql/binary  -> /srv/mysql/ssd/binary
  /var/lib/mysql/data    -> /srv/mysql/sas/data

Can you please help me understanding what is going on with my database server?
Why is it slowing down service and increasing the InnoDB Buffer Pool Write activity?

Best Answer

The symptoms I've describe are matching with dirty-page-flushing issues in my InnoDB Buffer pool. Dirty pages get flushed from the InnoDB Buffer Pool, among other situations, when InnoDB recycles one of it's Journal Files. This cause en-mass flushing of Data Pages to the disk, which causes I/O Bursts.

The links below suggest some insight on the problem.

http://www.mysqlperformanceblog.com/2008/11/13/adaptive-checkpointing/ http://dimitrik.free.fr/blog/archives/07-01-2010_07-31-2010.html http://www.chriscalender.com/?p=201

The solution passes through choosing either:

Increase the number of the InnoDB Log Files in use, in order to increase the Maximum Checkpoint Age available;
Change the Checkpointing strategy (variable innodb_adaptive_checkpoint) to a more aggressive strategy;
Tuning innodb_io_capacity and the size of InnoDB Log File and Buffer sizes.

Related Solutions

MySQL – Master Binlog Corruption

Surprisingly, that's not gibberish.

That indeed appears at the top of binlogs whenever you do mysqlbinlog to a binary log generated using MySQL 5.1 and MySQL 5.5. You will not see that gibberish in binary logs for MySQL 5.0 and back.

This is why the start point for replication from an empty binary log is

107 for MySQL 5.5
106 for MySQL 5.1
98 for MySQL 5.0 and back

This is good to remember if you do MySQL Replication where the Master if MySQL 5.1 and the slave is MySQL 5.0. This could present a really big headache.

Replication from Master using 5.0 and Slave using 5.1 works fine, not the other way around.(According to MySQL Documentation, it is generally not supported for 3 reasons: 1) Binary Log Format, 2) Row-based Replication, 3) SQL Incompatibility).

Anyway, do a mysqlbinlog on the offending binary log on the master. If the resulting dump produces gibberish in the middle of the dump (which I have seen a couple of times in my DBA career) you may have to skip to position 98 (MySQL 5.0) or 106 (MySQL 5.1) or 107 (MySQL 5.5) of the master's next binary log and start replicating from there (SOB :( you may need to use MAATKIT tools mk-table-checksum and mk-table-sync to reload master changes not on the slave [if you want to be a hero]; even worse, mysqldump the master and reload the slave and start replication totally over [if you don't want to be a hero])

If the mysqlbinlog of the master is completely readable after the top gibberish you saw, it is possible the master's binary log is fine but the relay log on the slave is corrupt (due to transmission/CRC errors). If that's the case, just reload the relay logs by issuing the CHANGE MASTER TO command as follows:

STOP SLAVE;
CHANGE MASTER TO
MASTER_HOST='< master-host ip or DNS >',
MASTER_PORT=3306,
MASTER_USER='< usernmae >',
MASTER_PASSWORD='< password >',
MASTER_LOG_FILE='< MMMM >',
MASTER_LOG_POS=< PPPP >;
START SLAVE;

Where

MMMM is the last file used from the Master that was last processed on the Slave
PPPP is the last position used from the Master that was last processed on the Slave

You can get MMMM and PPPP by doing SHOW SLAVE STATUS\G and using

Relay_Master_Log_File for MMMM
Exec_Master_Log_Pos for PPPP

Try it out and let me know !!!

BTW running CHANGE MASTER TO command erases the slave's current relay logs and starts fresh.

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

The two answers given from @RickJames and @drogart are essentially the remedies. (+1 for each).

Right from the error log you present, the last two lines say:

InnoDB: Error: log file ./ib_logfile0 is of different size 0 134217728 bytes

InnoDB: than specified in the .cnf file 0 268435456 bytes! `

At that point, it was evident that you set innodb_log_file_size to 256M (268435456) in my.cnf while the InnoDB Transaction Logs (ib_logfile0,ib_logfile1) were respectively 128M (134217728) each. Looking back at the link to my StackOverflow answer in your question, you had to do the following:

Step 01) Add this to my.cnf:

[mysqld]
innodb_buffer_pool_size=4G
innodb_log_file_size=1G

Step 02) Run these command in the OS

mysql -u... -p... -e"SET GLOBAL innodb_fast_shutdown = 1"
service mysql stop
rm -f /var/lib/mysql/ib_logfile*
service mysql start

So as to have confidence in what is happening, run tail -f against the error log. You will see message telling you when each innodb log file is being created.

Best Answer

Related Solutions

MySQL – Master Binlog Corruption

MySQL – Troubleshooting Startup Issues After Increasing innodb_buffer_pool_size

Related Question