MySQL Bugs: #62478: Creation of big innodb_log

Bug #62478	Creation of big innodb_log_file takes too long
Submitted:	20 Sep 2011 0:21	Modified:	2 Aug 2012 18:36
Reporter:	Vadim TKACHENKO	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S5 (Performance)
Version:	MySQL 5.6.3, 5.6.4	OS:	Any
Assigned to:	Inaam Rana	CPU Architecture:	Any

Description:
I tried to start MySQL 5.6.3
with innodb_log_file_size=32G ( two files, 64GB in total).

it took two hours to get to 50GB and process seemed slowed down with each new GB, so I had to kill it.

How to repeat:
Start mysqld with innodb_log_file_size=32G

This is what I see with smaller values:

macbook-pro:trunk openxs$ bin/mysqld_safe --innodb_log_file_size=2G &
[1] 76445
macbook-pro:trunk openxs$ 110920 13:04:24 mysqld_safe Logging to '/Users/openxs/dbs/trunk/data/macbook-pro.err'.
chown: /Users/openxs/dbs/trunk/data/macbook-pro.err: Operation not permitted
110920 13:04:24 mysqld_safe Starting mysqld daemon with databases from /Users/openxs/dbs/trunk/data

macbook-pro:trunk openxs$ tail -f data/macbook-pro.err 
110920 13:04:24 InnoDB: The InnoDB memory heap is disabled
110920 13:04:24 InnoDB: Mutexes and rw_locks use GCC atomic builtins
110920 13:04:24 InnoDB: Compressed tables use zlib 1.2.3
110920 13:04:24 InnoDB: CPU does not support crc32 instructions
110920 13:04:24 InnoDB: Initializing buffer pool, size = 128.0M
110920 13:04:24 InnoDB: Completed initialization of buffer pool
110920 13:04:24  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 2048 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
110920 13:05:19  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 2048 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
110920 13:06:20 InnoDB: highest supported file format is Barracuda.

So, for 2x2G it took 1 min 56 seconds to create them both. Now, for 2x4G:

macbook-pro:trunk openxs$ bin/mysqld_safe --innodb_log_file_size=4G &
[1] 76549
macbook-pro:trunk openxs$ 110920 13:47:49 mysqld_safe Logging to '/Users/openxs/dbs/trunk/data/macbook-pro.err'.
chown: /Users/openxs/dbs/trunk/data/macbook-pro.err: Operation not permitted
110920 13:47:49 mysqld_safe Starting mysqld daemon with databases from /Users/openxs/dbs/trunk/data

macbook-pro:trunk openxs$ tail -f data/macbook-pro.err 
110920 13:47:49 InnoDB: The InnoDB memory heap is disabled
110920 13:47:49 InnoDB: Mutexes and rw_locks use GCC atomic builtins
110920 13:47:49 InnoDB: Compressed tables use zlib 1.2.3
110920 13:47:49 InnoDB: CPU does not support crc32 instructions
110920 13:47:49 InnoDB: Initializing buffer pool, size = 128.0M
110920 13:47:49 InnoDB: Completed initialization of buffer pool
110920 13:47:49  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 4096 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 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000
110920 13:49:48  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 4096 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 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000
110920 13:53:18 InnoDB: highest supported file format is Barracuda.

it took 5 mins 29 seconds, and for 2x5G:

110920 14:23:39  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5120 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 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000 4100 4200 4300 4400 4500 4600 4700 4800 4900 5000 5100
110920 14:26:24  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5120 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 2100 2200 2300 2400 2500 2600 2700 2800 2900 3000 3100 3200 3300 3400 3500 3600 3700 3800 3900 4000 4100 4200 4300 4400 4500 4600 4700 4800 4900 5000 5100
110920 14:31:42 InnoDB: highest supported file format is Barracuda.

it took 8 minutes and 3 seconds, more than 5 mins for second 5G log file, comparing to less than 1 minute for second 2G log file above.

I am sure it depends on OS, filesystem, free space on disk etc (and I'll check on Linux with bigger files later), but non-linear nature of this process seems obvious.

One thing to watch out for is whether or not the system starts swapping. IIRC linux has some config parameter which sets the 'swappiness' of the system. Linux kernel can decide to swap out some memory instead of evicting file system buffers. If that happens it can be one cause of non-linear time required for creation of redo log files.

I've checked today on Linux (with 5.6.4), with size up to 30G, and do not see any serious problem there:

110921 10:29:41  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 30720 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 
...
30300 30400 30500 30600 30700
110921 10:35:47  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 30720 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 
...
30300 30400 30500 30600 30700
110921 10:41:54 InnoDB: highest supported file format is Barracuda.
...

So, it takes 12 mins or so, while with 10G it took 4 minutes. Not fast, but not hours to wait, and almost linear time growth with size.

Linux info:

[openxs@chief trunk]$ uname -a
Linux chief 2.6.35.14-96.fc14.x86_64 #1 SMP Thu Sep 1 11:59:56 UTC 2011 x86_64 x86_64 x86_64 GNU/Linux
[openxs@chief trunk]$ free
             total       used       free     shared    buffers     cached
Mem:       2021576     772032    1249544          0      34820     230780
-/+ buffers/cache:     506432    1515144
Swap:      4194300          0    4194300
[openxs@chief trunk]$ df -k
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/sda1            100791728  19433492  80334492  20% /
tmpfs                  1010788       548   1010240   1% /dev/shm
...
[openxs@chief trunk]$ mount
/dev/sda1 on / type ext4 (rw)
proc on /proc type proc (rw)
sysfs on /sys type sysfs (rw)
devpts on /dev/pts type devpts (rw,gid=5,mode=620)
tmpfs on /dev/shm type tmpfs (rw,rootcontext="system_u:object_r:tmpfs_t:s0")
none on /proc/sys/fs/binfmt_misc type binfmt_misc (rw)
fusectl on /sys/fs/fuse/connections type fusectl (rw)
...

So, looks like the result with really depend on OS and filesystem and hardware.

Added to changelog for 5.6.7, 5.7.0: 

Creating large InnoDB log files on a Linux system could cause
swapping, depending on the size of the log files and the available
RAM. This fix uses the O_DIRECT setting while creating the log files
to avoid filling up memory buffers with unnecessary data.

Removing changelog entry because fix was reverted - caused other types of performance issues.