Slowing down transaction log init

Summary:
This diff added a configurable variable to throttle the write rate of
new innodb log file initialization. Default speed is 128MB/second, and
setting it to 0 will turn off the throttling.

I also changed the default value of innodb_fsync_freq to 1MB to reduce
system stalls caused by fsyncing large trunks of file.

Test Plan:
jenkins

Testing command:
  mysqld --datadir=/tmp/log_init --skip-grant-tables --skip-networking --socket=socket --innodb-log-file-size=1G --innodb-txlog-init-rate=[rate]

With --innodb-txlog-init-rate=0 (no throttling, 1GB init finished in ~49s)

  2015-05-22 16:51:20 4018018 [Note] InnoDB: Setting log file ./ib_logfile101 size to 1024 MB
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
  2015-05-22 16:52:09 4018018 [Note] InnoDB: Setting log file ./ib_logfile1 size to 1024 MB
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

With --innodb-txlog-init-rate=10485760 (10MB/s throttling, 1GB log init finished in ~103s)

  2015-05-22 16:55:28 4022136 [Note] InnoDB: Setting log file ./ib_logfile101 size to 1024 MB
  InnoDB: log file write is throttled at 10MB/s
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
  2015-05-22 16:57:11 4022136 [Note] InnoDB: Setting log file ./ib_logfile1 size to 1024 MB
  InnoDB: log file write is throttled at 10MB/s
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

Without setting the option (use default. 1GB init finished in ~50s. Note the write is already below 128MB/s, so the throttling didn't have any effect)

  2015-05-22 17:18:51 4055898 [Note] InnoDB: Setting log file ./ib_logfile101 size to 1024 MB
  InnoDB: log file write is throttled at 128MB/s
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
  2015-05-22 17:19:41 4055898 [Note] InnoDB: Setting log file ./ib_logfile1 size to 1024 MB
  InnoDB: log file write is throttled at 128MB/s
  InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000

Reviewers: jtolmer

Reviewed By: jtolmer

mysql-test/suite/sys_vars/r/innodb_fsync_freq_basic.result

@@ -1,7 +1,7 @@
 SET @orig_fsync_freq = @@global.innodb_fsync_freq;
 SELECT @orig_fsync_freq;
 @orig_fsync_freq
-134217728
+1048576
 SET GLOBAL innodb_fsync_freq = 1024*1024*1024;
 SELECT @@global.innodb_fsync_freq;
 @@global.innodb_fsync_freq

mysql-test/suite/sys_vars/r/innodb_txlog_init_rate_basic.result

@@ -0,0 +1,25 @@
+SET @orig_txlog_init_rate = @@global.innodb_txlog_init_rate;
+SELECT @orig_txlog_init_rate;
+@orig_txlog_init_rate
+134217728
+SET GLOBAL innodb_txlog_init_rate = 500*1024*1024;
+SELECT @@global.innodb_txlog_init_rate;
+@@global.innodb_txlog_init_rate
+524288000
+SET GLOBAL innodb_txlog_init_rate = 0;
+SELECT @@global.innodb_txlog_init_rate;
+@@global.innodb_txlog_init_rate
+0
+SET GLOBAL innodb_txlog_init_rate = -1;
+Warnings:
+Warning	1292	Truncated incorrect innodb_txlog_init_rate value: '-1'
+SELECT @@global.innodb_txlog_init_rate;
+@@global.innodb_txlog_init_rate
+0
+SET GLOBAL innodb_txlog_init_rate = 12345;
+Warnings:
+Warning	1292	Truncated incorrect innodb_txlog_init_rate value: '12345'
+SELECT @@global.innodb_txlog_init_rate;
+@@global.innodb_txlog_init_rate
+0
+SET GLOBAL innodb_txlog_init_rate = @orig_txlog_init_rate;

mysql-test/suite/sys_vars/t/innodb_txlog_init_rate_basic.test

@@ -0,0 +1,25 @@
+--source include/have_innodb.inc
+
+
+SET @orig_txlog_init_rate = @@global.innodb_txlog_init_rate;
+
+SELECT @orig_txlog_init_rate;
+
+# 500MB/s
+SET GLOBAL innodb_txlog_init_rate = 500*1024*1024;
+SELECT @@global.innodb_txlog_init_rate;
+
+# min value
+SET GLOBAL innodb_txlog_init_rate = 0;
+SELECT @@global.innodb_txlog_init_rate;
+
+# invalid value
+# too small
+SET GLOBAL innodb_txlog_init_rate = -1;
+SELECT @@global.innodb_txlog_init_rate;
+
+# not bound to page size
+SET GLOBAL innodb_txlog_init_rate = 12345;
+SELECT @@global.innodb_txlog_init_rate;
+
+SET GLOBAL innodb_txlog_init_rate = @orig_txlog_init_rate;

storage/innobase/handler/ha_innodb.cc

@@ -18175,9 +18175,17 @@ static MYSQL_SYSVAR_ULONG(spin_wait_delay, srv_spin_wait_delay,
 static MYSQL_SYSVAR_ULONGLONG(fsync_freq, os_fsync_freq,
   PLUGIN_VAR_RQCMDARG,
   "The value of this variable determines how often InnoDB calls fsync when "
-  "creating a new file. Default is to call fsync after every 128M written. "
-  "Setting this value to zero would make InnoDB flush the file before closing "
-  "it.", NULL, NULL, 1ULL << 27, 0, ULONG_MAX, UNIV_PAGE_SIZE);
+  "creating a new file. Default is to call fsync after every time the buffer "
+  "(1MB) is written. Setting this value to zero would make InnoDB flush the "
+  "file before closing it.",
+  NULL, NULL, OS_FILE_WRITE_BUF_SIZE, 0, ULONG_MAX, OS_FILE_WRITE_BUF_SIZE);
+
+static MYSQL_SYSVAR_ULONGLONG(txlog_init_rate, os_txlog_init_rate,
+  PLUGIN_VAR_OPCMDARG,
+  "The value of this variable determines how fast (in bytes/s) InnoDB "
+  "initializes the transaction log when creating a new file"
+  "Setting this value to 0 means no limit. Default is 128MB",
+  NULL, NULL, 1ULL << 27, 0ULL, ULONG_MAX, 1ULL << 20);
 
 static MYSQL_SYSVAR_UINT(load_table_thread_num, innobase_load_table_thread_num,
   PLUGIN_VAR_RQCMDARG,
@@ -18688,6 +18696,7 @@ static struct st_mysql_sys_var* innobase_system_variables[]= {
   MYSQL_SYSVAR(sync_spin_loops),
   MYSQL_SYSVAR(spin_wait_delay),
   MYSQL_SYSVAR(fsync_freq),
+  MYSQL_SYSVAR(txlog_init_rate),
   MYSQL_SYSVAR(load_table_thread_num),
   MYSQL_SYSVAR(table_locks),
   MYSQL_SYSVAR(thread_concurrency),

storage/innobase/include/os0file.h

@@ -142,6 +142,8 @@ enum os_file_create_t {
 					ON_ERROR_NO_EXIT is set */
 };
 
+#define OS_FILE_WRITE_BUF_SIZE 1ULL<<20
+
 #define OS_FILE_READ_ONLY		333
 #define	OS_FILE_READ_WRITE		444
 #define	OS_FILE_READ_ALLOW_DELETE	555	/* for mysqlbackup */
@@ -227,6 +229,7 @@ extern ulint	os_n_file_reads;
 extern ulint	os_n_file_writes;
 extern ulint	os_n_fsyncs;
 extern ullint	os_fsync_freq;
+extern ullint	os_txlog_init_rate;
 
 /** Seconds waiting for file flushes to finish */
 extern ulonglong	os_file_flush_time;

storage/innobase/os/os0file.cc

@@ -95,7 +95,8 @@ UNIV_INTERN ulint	os_innodb_umask = S_IRUSR | S_IWUSR | S_IRGRP | S_IWGRP;
 UNIV_INTERN ulint	os_innodb_umask	= 0;
 #endif /* __WIN__ */
 
-UNIV_INTERN ullint os_fsync_freq = 1ULL << 27;
+UNIV_INTERN ullint os_fsync_freq = OS_FILE_WRITE_BUF_SIZE;
+UNIV_INTERN ullint os_txlog_init_rate = 1ULL << 27;
 
 #ifndef UNIV_HOTBACKUP
 /* We use these mutexes to protect lseek + file i/o operation, if the
@@ -2322,9 +2323,8 @@ os_file_set_size(
 
 	current_size = 0;
 
-	/* Write up to 1 megabyte at a time. */
-	buf_size = ut_min(64, (ulint) (size / UNIV_PAGE_SIZE))
-		* UNIV_PAGE_SIZE;
+	/* Write 1 megabyte at a time. */
+	buf_size = OS_FILE_WRITE_BUF_SIZE;
 	buf2 = static_cast<byte*>(ut_malloc(buf_size + UNIV_PAGE_SIZE));
 
 	/* Align the buffer for possible raw i/o */
@@ -2333,11 +2333,17 @@ os_file_set_size(
 	/* Write buffer full of zeros */
 	memset(buf, 0, buf_size);
 
+	if (os_txlog_init_rate > 0) {
+		fprintf(stderr, "InnoDB: log file write is throttled at %lluMB/s\n",
+				os_txlog_init_rate/(1ULL<<20));
+	}
+
 	if (size >= (os_offset_t) 100 << 20) {
 
 		fprintf(stderr, "InnoDB: Progress in MB:");
 	}
 
+	ulonglong start_time = my_timer_now();
 	while (current_size < size) {
 		ulint	n_bytes;
 
@@ -2353,6 +2359,14 @@ os_file_set_size(
 			goto error_handling;
 		}
 
+		if (os_txlog_init_rate > 0) {
+			/* check write rate on every chunk (1MB) we write */
+			while ((double)(current_size + n_bytes) > os_txlog_init_rate *
+					my_timer_to_seconds(my_timer_since(start_time))) {
+				os_thread_sleep(1000); /* sleep for 1000 usecs */
+			}
+		}
+
 		/* Print about progress for each 100 MB written */
 		if ((current_size + n_bytes) / (100 << 20)
 		    != current_size / (100 << 20)) {