Bug #11725 innodb-safe-binlog option - performance overkill for MyISAM
Submitted: 4 Jul 2005 15:57 Modified: 17 Jul 2005 19:33
Reporter: Martin Pala Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Replication Severity:S3 (Non-critical)
Version:4.1.10a OS:Linux (Redhat Enterprise Linux 4.0)
Assigned to: Sergei Golubchik CPU Architecture:Any

[4 Jul 2005 15:57] Martin Pala
Description:
We tried to setup MySQL replication master.

For best consistency MySQL recommends to use innodb transactional engine and innodb-safe-binlog option, which ensures, that the possible transaction rollback will be safe.

See the my.cnf in the attachment for our configuration.

Initialy we performed the tests with production data on InnoDB engine, however we observed bad performance 25 writes/s with innodb-safe-binlog (sync_binlog=1), resp. 150 writes/s with innodb-safe-binlog disabled (sync_binlog=0).

Thus we tried MyISAM and reached the same result ... it seemed strange.

To recreate the situation i have prepared sample scheme (same as production table, but the attribute names were replaced by symbolic names) and sample entries (for testing purpose are all columns static except the primary key).

The scheme is simple (the production table column names were hidden, but the structure is kept):

CREATE TABLE test (
  date1 datetime             default NULL,
  text1 varchar(10) NOT NULL default '',
  text2 varchar(32) NOT NULL default '',
  text3 char(2)              default NULL,
  num1  int(11)              default NULL,
  date2 date                 default NULL,
  num2  int(11)     NOT NULL default '0',
  date3 datetime             default NULL,
  date4 date                 default NULL,
  date5 date                 default NULL,
  PRIMARY KEY (text2)
) TYPE=InnoDB;

The test data were prepared using the script bellow (500k sample entries - all columns are static except the text2 ... real database entries columns are heterogenous of course ;)

i=500000; while [ $i -gt 0 ]; do dd if=/dev/urandom bs=8 count=1 | uuencode -m /dev/stdout | awk 'NR==2 {print "INSERT INTO test VALUES (\"2004-09-10 14:32:43\",\"123456789\",\""$0"\",\"cz\",NULL,\"2001-06-18\",1,\"2001-06-18 20:42:28\",\"2001-06-18\",\"0000-00-00\");"}'; i=$[i-1]; done >> test.sql 2>/dev/null

Test #1 (MyISAM engine + binlog + innodb-safe-binlog):
-----------
Using the MyISAM storage engine we've reached ca. 22 writes/s (sync_binlog was enabled by default).
With sync_binlog disabled ("set global sync_binlog=0") we reached ca. 160 writes/s.
In both cases the disk was saturated by writes. 

[root@l1smse01 ~]# iostat -xd 5
Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
cciss/c0d0   0.00  35.77  0.00 145.33    0.00 1450.41     0.00   725.20     9.98     1.42    9.72   6.97 101.24

[root@l1smse01 ~]# mysqladmin -i 10 -r -u test extended-status | awk '$2 ~ /_write/ {print; fflush()}'
| Delayed_writes           | 0        |
| Handler_write            | 223      |
| Key_write_requests       | 235      |
| Key_writes               | 235      |

| Delayed_writes           | 0        |
| Handler_write            | 224      |
| Key_write_requests       | 234      |
| Key_writes               | 234      |

| Delayed_writes           | 0        |
| Handler_write            | 223      |
| Key_write_requests       | 233      |
| Key_writes               | 233      |

Test #2 (MyISAM engine + binlog - no innodb-safe-binlog):
-----------
Then i tried to disable the innodb-safe-binlog option: this time we reached ca. 7500 writes/s.

[root@l1smse01 ~]# iostat -xd 5
Device:    rrqm/s wrqm/s   r/s   w/s  rsec/s  wsec/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
cciss/c0d0   0.00 1227.08  0.00 207.04    0.00 11732.20     0.00  5866.10    56.67    71.58  345.62   1.58  32.79

[root@l1smse01 ~]# mysqladmin -i 10 -r -u test extended-status | awk '$2 ~ /_write/ {print; fflush()}'
| Delayed_writes           | 0        |
| Handler_write            | 75358    |
| Key_write_requests       | 79005    |
| Key_writes               | 79006    |

| Delayed_writes           | 0        |
| Handler_write            | 73331    |
| Key_write_requests       | 76640    |
| Key_writes               | 76640    |

| Delayed_writes           | 0        |
| Handler_write            | 76099    |
| Key_write_requests       | 79955    |
| Key_writes               | 79955    |

Summary:
When enabled, innodb-safe-binlog option drops performance by more then one order even if no InnoDB engine is used. It seems that it is highly ineffective (drop from 7500 w/s -> 160 w/s with sync_binlog disabled in both cases).

How to repeat:
Here is our configuration:

[root@l1smse01 ~]# awk '$0 !~ /(^#)|(^\s*$)/ {print}' /etc/my.cnf
[client]
port    = 3306
socket      = /var/lib/mysql/mysql.sock
[mysqld]
datadir         = /app01/mysql/data
tmpdir      = /app01/mysql/tmp/
log-update          = /app01/mysql/log/
log-error       = /var/log/mysqld.log
socket      = /var/lib/mysql/mysql.sock
port    = 3306
key_buffer          = 256M
max_allowed_packet    = 1M
max_connections       = 300
table_cache           = 256
sort_buffer_size      = 1M
read_buffer_size      = 1M
read_rnd_buffer_size   = 4M
myisam_sort_buffer_size  = 64M
thread_cache          = 8
query_cache_size      = 16M
thread_concurrency    = 8
skip-locking
skip-bdb
log-bin         = /app01/mysql/log/log-bin
max_binlog_size       = 10485760
server-id       = 1
innodb_data_home_dir        = /app01/mysql/data
innodb_data_file_path       = ibdata1:100M:autoextend
innodb_log_group_home_dir   = /app01/mysql/data/
innodb_log_arch_dir         = /app01/mysql/data/
innodb_buffer_pool_size  = 256M
innodb_additional_mem_pool_size = 20M
innodb_log_file_size   = 64M
innodb_log_buffer_size   = 8M
innodb_flush_log_at_trx_commit  = 1
innodb_lock_wait_timeout    = 50
[mysqldump]
quick
max_allowed_packet    = 16M
[mysql]
no-auto-rehash
[isamchk]
key_buffer          = 128M
sort_buffer_size      = 128M
read_buffer           = 2M
write_buffer          = 2M
[myisamchk]
key_buffer          = 128M
sort_buffer_size      = 128M
read_buffer           = 2M
write_buffer          = 2M
[mysqlhotcopy]
interactive-timeout
[mysql.server]
user    = mysql
basedir         = /var/lib
[mysqld_safe]
err-log         = /var/log/mysqld.log
pid-file        = /var/run/mysqld/mysqld.pid

And sample sql script:
--8<--
CREATE DATABASE /*!32312 IF NOT EXISTS*/ repltest;

USE repltest;

DROP TABLE IF EXISTS `test`;

CREATE TABLE test (
  date1 datetime             default NULL,
  text1 varchar(10) NOT NULL default '',
  text2 varchar(32) NOT NULL default '',
  text3 char(2)              default NULL,
  num1  int(11)              default NULL,
  date2 date                 default NULL,
  num2  int(11)     NOT NULL default '0',
  date3 datetime             default NULL,
  date4 date                 default NULL,
  date5 date                 default NULL,
  KEY text2 (text2)
) TYPE=MyISAM;
--8<--

+ this script generates sample data:
i=500000; while [ $i -gt 0 ]; do dd if=/dev/urandom bs=8 count=1 | uuencode -m /dev/stdout | awk 'NR==2 {print "INSERT INTO test VALUES (\"2004-09-10 14:32:43\",\"123456789\",\""$0"\",\"cz\",NULL,\"2001-06-18\",1,\"2001-06-18 20:42:28\",\"2001-06-18\",\"0000-00-00\");"}'; i=$[i-1]; done >> test.sql 2>/dev/null

Try to import the data:
1.) using innodb-safe-binlog option
2.) without innodb-safe-binlog option
[4 Jul 2005 16:00] Martin Pala
MySQL configuration

Attachment: my.cnf (application/octet-stream, text), 1.75 KiB.

[17 Jul 2005 19:33] Sergei Golubchik
Thank you for taking the time to write to us, but this is not
a bug. Please double-check the documentation available at
http://www.mysql.com/documentation/ and the instructions on
how to report a bug at http://bugs.mysql.com/how-to-report.php

Additional info:

If you check the error log, you'll see that innodb-safe-binlog causes sync-binlog=1. The latter makes binlog to be synced to disk after every statement, so a slowdown is expected even if InnoDB is not used.