FB8-52: Slowing down transaction log init (#931)

Summary:
JIRA: https://jira.percona.com/browse/FB8-52

Reference Patch: 80ca845
Reference Patch: 0fb428b

Patch introduces new variable 'innodb_txlog_init_rate' to limit
the IO rate of InnoDB redo log file initialization.
Pull Request resolved: #931

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

Reviewed By: lth

Differential Revision: D13789095

Pulled By: lth

fbshipit-source-id: 8c94859

mysql-test/r/all_persisted_variables.result

@@ -37,17 +37,17 @@ include/assert.inc [Expect 500+ variables in the table. Due to open Bugs, we are
 
 # Test SET PERSIST
 
-include/assert.inc [Expect 404 persisted variables in the table.]
+include/assert.inc [Expect 405 persisted variables in the table.]
 
 ************************************************************
 * 3. Restart server, it must preserve the persisted variable
 *    settings. Verify persisted configuration.
 ************************************************************
 # restart
 
-include/assert.inc [Expect 404 persisted variables in persisted_variables table.]
-include/assert.inc [Expect 404 persisted variables shown as PERSISTED in variables_info table.]
-include/assert.inc [Expect 404 persisted variables with matching peristed and global values.]
+include/assert.inc [Expect 405 persisted variables in persisted_variables table.]
+include/assert.inc [Expect 405 persisted variables shown as PERSISTED in variables_info table.]
+include/assert.inc [Expect 405 persisted variables with matching peristed and global values.]
 
 ************************************************************
 * 4. Test RESET PERSIST IF EXISTS. Verify persisted variable

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,22 @@
+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;

mysql-test/t/all_persisted_variables.test

@@ -39,7 +39,7 @@
 call mtr.add_suppression("Failed to set up SSL because of the following SSL library error");
 
 let $total_global_vars=`SELECT COUNT(*) FROM performance_schema.global_variables where variable_name NOT LIKE 'ndb_%'`;
-let $total_persistent_vars=404;
+let $total_persistent_vars=405;
 
 --echo ***************************************************************
 --echo * 0. Verify that variables present in performance_schema.global

storage/innobase/handler/ha_innodb.cc

@@ -22015,6 +22015,13 @@ static MYSQL_SYSVAR_ULONGLONG(
     "entire file at once before closing it.",
     NULL, NULL, 0, 0, ~0ULL, UNIV_PAGE_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",
+    nullptr, nullptr, 1ULL << 27, 0ULL, ULONG_MAX, 1ULL << 20);
+
 static MYSQL_SYSVAR_ULONG(thread_concurrency, srv_thread_concurrency,
                           PLUGIN_VAR_RQCMDARG,
                           "Helps in performance tuning in heavily concurrent "
@@ -22514,6 +22521,7 @@ static SYS_VAR *innobase_system_variables[] = {
     MYSQL_SYSVAR(spin_wait_delay),
     MYSQL_SYSVAR(spin_wait_pause_multiplier),
     MYSQL_SYSVAR(fsync_threshold),
+    MYSQL_SYSVAR(txlog_init_rate),
     MYSQL_SYSVAR(table_locks),
     MYSQL_SYSVAR(thread_concurrency),
     MYSQL_SYSVAR(adaptive_max_sleep_delay),

storage/innobase/include/os0file.h

@@ -77,6 +77,10 @@ extern ulint os_n_pending_writes;
 /* Flush after each os_fsync_threshold bytes */
 extern unsigned long long os_fsync_threshold;
 
+/** This is used to limit the IO write rate during
+initalization of redo log. Unit is bytes/second */
+extern unsigned long long os_txlog_init_rate;
+
 /** Number of outstanding aio requests */
 extern ulint os_aio_n_outstanding;
 #ifdef UNIV_DEBUG
@@ -823,7 +827,6 @@ enum class AIO_mode : size_t {
 extern ulint os_n_file_reads;
 extern ulint os_n_file_writes;
 extern ulint os_n_fsyncs;
-
 /* File types for directory entry data type */
 
 enum os_file_type_t {
@@ -1611,10 +1614,11 @@ os_offset_t os_file_get_size(pfs_os_file_t file)
 @param[in]	size		file size
 @param[in]	read_only	Enable read-only checks if true
 @param[in]	flush		Flush file content to disk
+@param[in]	throttle	throttle the initialization IO write rate
 @return true if success */
 bool os_file_set_size(const char *name, pfs_os_file_t file, os_offset_t offset,
-                      os_offset_t size, bool read_only, bool flush)
-    MY_ATTRIBUTE((warn_unused_result));
+                      os_offset_t size, bool read_only, bool flush,
+                      bool throttle = false) MY_ATTRIBUTE((warn_unused_result));
 
 /** Truncates a file at its current position.
 @param[in,out]	file	file to be truncated

storage/innobase/os/os0file.cc

@@ -100,6 +100,9 @@ Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301  USA
 /* Flush after each os_fsync_threshold bytes */
 unsigned long long os_fsync_threshold = 0;
 
+/* Redo log initialization rate (128MB) */
+unsigned long long os_txlog_init_rate = 1ULL << 27;
+
 /** Insert buffer segment id */
 static const ulint IO_IBUF_SEGMENT = 0;
 
@@ -5543,9 +5546,11 @@ void os_file_set_nocache(int fd MY_ATTRIBUTE((unused)),
 @param[in]	size		file size
 @param[in]	read_only	Enable read-only checks if true
 @param[in]	flush		Flush file content to disk
+@param[in]	throttle	throttle the initialization IO write rate
 @return true if success */
 bool os_file_set_size(const char *name, pfs_os_file_t file, os_offset_t offset,
-                      os_offset_t size, bool read_only, bool flush) {
+                      os_offset_t size, bool read_only, bool flush,
+                      bool throttle) {
   /* Write up to FSP_EXTENT_SIZE bytes at a time. */
   ulint buf_size = 0;
 
@@ -5576,6 +5581,7 @@ bool os_file_set_size(const char *name, pfs_os_file_t file, os_offset_t offset,
 
   os_offset_t current_size = offset;
 
+  ulonglong start_time = my_timer_now();
   while (current_size < size) {
     ulint n_bytes;
 
@@ -5605,6 +5611,15 @@ bool os_file_set_size(const char *name, pfs_os_file_t file, os_offset_t offset,
       return (false);
     }
 
+    if (os_txlog_init_rate > 0 && throttle) {
+      /* 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)) {
       fprintf(stderr, " %lu00",

storage/innobase/srv/srv0start.cc

@@ -312,7 +312,7 @@ static MY_ATTRIBUTE((warn_unused_result)) dberr_t
 #endif /* UNIV_DEBUG_DEDICATED */
 
   ret = os_file_set_size(name, *file, 0, (os_offset_t)srv_log_file_size,
-                         srv_read_only_mode, true);
+                         srv_read_only_mode, true, true);
 
   if (!ret) {
     ib::error(ER_IB_MSG_1063, name, size);