Bug #12125 Massive Disk I/O Degradation under 4.1.13 in OS X
Submitted: 22 Jul 2005 22:59 Modified: 26 Jul 2005 21:40
Reporter: Bruce Dembecki Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:4.1.13 OS:MacOS (OS X 10.4.2)
Assigned to: Marko Mäkelä CPU Architecture:Any

[22 Jul 2005 22:59] Bruce Dembecki
Description:
Installing a new server to replace an old server... server is dedicated to MySQL so no other processes running. Data disks are on a Fiber Channel connection to a seven spindle raid 5. "mysql" database copied from an active server, datadir otherwise empty. InnoDB told to create a 2000M data file and 2 x 250Mbyte log files.

Upon launching the server it takes ~55 minutes to go from starting mysql to ready for connection, the time being consumed by InnoDB writing it's disks full... Same server, same setup but with 4.1.12 takes 4 minutes. Repeatable. Duplicated on another new server. Same results with 4.1.13 Standard and 4.1.13 Pro, althogg I didn't save the 4.1.13 Standard logs.

MySQL 4.1.13 Pro:    54 minutes 51 seconds
MySQL 4.1.12 Standard: 4 minutes 16 seconds

I don't have any evaluation of performance once launched, I figured Disk I/O is in trouble on 4.1.13 and haven't looked beyond that. I suppose while you guys look at the first part of the probelm I'll try something at my end and see what's after the InnoDB files are created. My Logs say:

[data-admin:/var/mysql] root# tail -f mysql.err
050722 13:51:08  mysqld started
InnoDB: The first specified data file /mysqldata/ibdata01 did not exist:
InnoDB: a new database to be created!
050722 13:51:09  InnoDB: Setting file /mysqldata/ibdata01 size to 2000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500 1600 1700 1800 1900 2000
050722 14:34:45  InnoDB: Log file /mysqldata/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /mysqldata/ib_logfile0 size to 250 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
050722 14:40:15  InnoDB: Log file /mysqldata2/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /mysqldata2/ib_logfile1 size to 250 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050722 14:45:59  InnoDB: Started; log sequence number 0 0
/usr/local/mysql/bin/mysqld: ready for connections.
Version: '4.1.13-pro-gpl-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Pro (GPL)

[data-admin:/var/mysql] root# tail -f mysql.err
050722 14:58:06  mysqld started
InnoDB: The first specified data file /mysqldata/ibdata01 did not exist:
InnoDB: a new database to be created!
050722 14:58:06  InnoDB: Setting file /mysqldata/ibdata01 size to 2000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300 1400 1500 1600 1700 1800 1900 2000
050722 15:01:22  InnoDB: Log file /mysqldata/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /mysqldata/ib_logfile0 size to 250 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
050722 15:01:47  InnoDB: Log file /mysqldata/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /mysqldata/ib_logfile1 size to 250 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050722 15:02:22  InnoDB: Started; log sequence number 0 0
/usr/local/mysql/bin/mysqld: ready for connections.
Version: '4.1.12-standard-log'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Edition - Standard (GPL)

After MySQL finishes creating the files and is running but sitting idle, duplicating the 2Gbyte file takes 22 seconds, so it is not a disk performance issue:

[data-admin:/var/mysql] root# time cp /mysqldata/ibdata01 /mysqldata/ibdatacopy
0.016u 5.571s 0:22.67 24.6%     0+0k 16+24io 0pf+0w

How to repeat:
In an empty data directory copy a "mysql" database so mysql can launch...

With the InnoDB portion of the my.cnf looking something like this (you may not have 2Gbytes of memory to throw at it):

innodb_data_file_path=ibdata01:2000M
innodb_log_group_home_dir = /mysqldata
set-variable = innodb_buffer_pool_size=1830M
set-variable = innodb_additional_mem_pool_size=256M
set-variable = innodb_log_files_in_group=2
set-variable = innodb_log_file_size=250M
set-variable = innodb_log_buffer_size=20M

Now start mysqld and refer to the logs to see how long it takes to go from "mysqld started" to "ready for connections". Compare this on 4.1.12 and 4.1.13.

Suggested fix:
I'm going to say build a 10.4 binary of MySQL... but that's just an ongoing issue I have, and may or may not be related to this bug... I don't know the cause of the problem so I don't have a fix.
[22 Jul 2005 23:05] Jim Winstead
This item from the ChangeLog appears to be a likely culprit:

* InnoDB: When creating or extending an InnoDB data file, allocate at most one megabyte at a time for initializing the file. Previously, InnoDB used to allocate and initialize 1 or 8 megabytes of memory, even if a few 16-kilobyte pages were to be written. This fix improves the performance of CREATE TABLE in innodb_file_per_table mode.
[23 Jul 2005 0:12] Heikki Tuuri
Hi!

The fix is to set os_do_not_call_flush_at_each_write = TRUE in os0file.c.

InnoDB always uses the doublewrite buffer. It is set to TRUE in the call of trx_doublewrite_init(), but we can set it earlier. Then we do not call unnecessary file flushes when we create the ibdata files.

os0file.c:

"
/* If the following is set to TRUE, we do not call os_file_flush in every
os_file_write. We can set this TRUE when the doublewrite buffer is used. */
ibool   os_do_not_call_flush_at_each_write      = FALSE;
"

I measured in our 4-way 700 MHz Xeon computer:

- Before the above fix the startup took 6.5 minutes.
- After the fix 4 minutes.
- 4.0 started up in 5 minutes.

Since Bruce's computer took 55 minutes to start up, it means that a file flush (the fcntl trick in OS X) takes an incredible 1.5 seconds in his computer! It is probably a performance bug in OS X. It revealed an inoptimality in InnoDB which we can fix with the little change above.

I am assigning this bug report to Marko.

Regards,

Heikki

heikki@hundin:~/mysql-5.0/innobase/trx> uname -a
Linux hundin 2.4.21-99-smp #1 SMP Wed Sep 24 13:31:14 UTC 2003 i686 i686 i386 GN
U/Linux

heikki@hundin:~/mysql-5.0/sql> ./mysqld
InnoDB: The first specified data file /home/heikki/data/ibdata1 did not exist:
InnoDB: a new database to be created!
050723  1:25:13  InnoDB: Setting file /home/heikki/data/ibdata1 size to 2000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300
1400 1500 1600 1700 1800 1900 2000
050723  1:30:57  InnoDB: Log file /home/heikki/data/ib_logfile0 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile0 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
050723  1:31:18  InnoDB: Log file /home/heikki/data/ib_logfile1 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile1 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050723  1:31:40  InnoDB: Started; log sequence number 0 0
050723  1:31:41 [Warning] './mysql/host' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:31:41 [Warning] './mysql/user' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:31:41 [Warning] './mysql/db' had no or invalid character set, and defa
ult character set is multi-byte, so character column sizes may have changed
050723  1:31:41 [Warning] mysql.user table is not updated to new password format
; Disabling new password usage until mysql_fix_privilege_tables is run
050723  1:31:41 [Warning] './mysql/tables_priv' had no or invalid character set,
 and default character set is multi-byte, so character column sizes may have cha
nged
050723  1:31:41 [Warning] './mysql/columns_priv' had no or invalid character set
, and default character set is multi-byte, so character column sizes may have ch
anged
050723  1:31:42 [Warning] './mysql/func' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:31:42 [Note] ./mysqld: ready for connections.
Version: '5.0.11-beta-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307
Source distribution

Below I recompiled with os_do_not_call_flush_at_each_write = TRUE:

heikki@hundin:~/mysql-5.0/sql> ./mysqld
InnoDB: The first specified data file /home/heikki/data/ibdata1 did not exist:
InnoDB: a new database to be created!
050723  1:37:58  InnoDB: Setting file /home/heikki/data/ibdata1 size to 2000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300
1400 1500 1600 1700 1800 1900 2000
050723  1:41:43  InnoDB: Log file /home/heikki/data/ib_logfile0 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile0 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
050723  1:41:54  InnoDB: Log file /home/heikki/data/ib_logfile1 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile1 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050723  1:42:05  InnoDB: Started; log sequence number 0 0
050723  1:42:05 [Warning] './mysql/host' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:42:05 [Warning] './mysql/user' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:42:05 [Warning] './mysql/db' had no or invalid character set, and defa
ult character set is multi-byte, so character column sizes may have changed
050723  1:42:05 [Warning] mysql.user table is not updated to new password format
; Disabling new password usage until mysql_fix_privilege_tables is run
050723  1:42:05 [Warning] './mysql/tables_priv' had no or invalid character set,
 and default character set is multi-byte, so character column sizes may have cha
nged
050723  1:42:05 [Warning] './mysql/columns_priv' had no or invalid character set
, and default character set is multi-byte, so character column sizes may have ch
anged
050723  1:42:05 [Warning] './mysql/func' had no or invalid character set, and de
fault character set is multi-byte, so character column sizes may have changed
050723  1:42:05 [Note] ./mysqld: ready for connections.
Version: '5.0.11-beta-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307
Source distribution

heikki@hundin:~/mysql-4.0/sql> ./mysqld
./mysqld: Character set 'utf8' is not a compiled character set and is not specif
ied in the '/home/heikki/share/mysql/charsets/Index' file
heikki@hundin:~/mysql-4.0/sql> ./mysqld
InnoDB: !!!!!!!!!!!!!! UNIV_DEBUG switched on !!!!!!!!!!!!!!!
InnoDB: The first specified data file /home/heikki/data/ibdata1 did not exist:
InnoDB: a new database to be created!
050723  1:43:54  InnoDB: Setting file /home/heikki/data/ibdata1 size to 2000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000 1100 1200 1300
1400 1500 1600 1700 1800 1900 2000
050723  1:47:57  InnoDB: Log file /home/heikki/data/ib_logfile0 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile0 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
050723  1:48:14  InnoDB: Log file /home/heikki/data/ib_logfile1 did not exist: n
ew to be created
InnoDB: Setting log file /home/heikki/data/ib_logfile1 size to 125 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
050723  1:48:42  InnoDB: Started
./mysqld: ready for connections.
Version: '4.0.25-debug-log'  socket: '/home/heikki/bugsocket'  port: 3307  Sourc
e distribution
[26 Jul 2005 12:04] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/27591
[26 Jul 2005 21:40] Marko Mäkelä
Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

Additional info:

The fix should appear in 5.0.11 and 4.1.14.