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

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

Reference Patch: facebook@80ca845
Reference Patch: facebook@0fb428b

Patch introduces new variable 'innodb_txlog_init_rate' to limit
the IO rate of InnoDB redo log file initialization.
Pull Request resolved: facebook#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/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;

storage/innobase/handler/ha_innodb.cc

@@ -21678,6 +21678,13 @@ static MYSQL_SYSVAR_ULONGLONG(
     "entire file at once before closing it.",
     nullptr, nullptr, 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 "
@@ -22185,6 +22192,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

@@ -79,6 +79,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
@@ -610,7 +614,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 {
@@ -1421,7 +1424,8 @@ zeros otherwise.
 @return true if success */
 bool os_file_set_size_fast(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));
+                           bool flush, bool throttle = false)
+    MY_ATTRIBUTE((warn_unused_result));
 
 /** Write the specified number of zeros to a file from specific offset.
 @param[in]	name		name of the file or path as a null-terminated
@@ -1431,10 +1435,11 @@ bool os_file_set_size_fast(const char *name, 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

@@ -102,6 +102,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;
 
@@ -5523,7 +5526,7 @@ void os_file_set_nocache(int fd MY_ATTRIBUTE((unused)),
 
 bool os_file_set_size_fast(const char *name, pfs_os_file_t pfs_file,
                            os_offset_t offset, os_offset_t size, bool read_only,
-                           bool flush) {
+                           bool flush, bool throttle) {
 #if !defined(NO_FALLOCATE) && defined(UNIV_LINUX) && \
     defined(HAVE_FALLOC_FL_ZERO_RANGE)
   ut_a(size >= offset);
@@ -5551,11 +5554,13 @@ bool os_file_set_size_fast(const char *name, pfs_os_file_t pfs_file,
   }
 #endif /* !NO_FALLOCATE && UNIV_LINUX && HAVE_FALLOC_FL_ZERO_RANGE */
 
-  return os_file_set_size(name, pfs_file, offset, size, read_only, flush);
+  return os_file_set_size(name, pfs_file, offset, size, read_only, flush,
+                          throttle);
 }
 
 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;
 
@@ -5585,6 +5590,7 @@ bool os_file_set_size(const char *name, pfs_os_file_t file, os_offset_t offset,
   /* Count to check and print progress of file write for file_size > 100 MB. */
   uint percentage_count = 10;
 
+  ulonglong start_time = my_timer_now();
   while (current_size < size) {
     ulint n_bytes;
 
@@ -5614,6 +5620,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 */
+      }
+    }
+
     /* Flush after each os_fsync_threhold bytes */
     if (flush && os_fsync_threshold != 0) {
       if ((current_size + n_bytes) / os_fsync_threshold !=

storage/innobase/srv/srv0start.cc

@@ -314,7 +314,7 @@ static MY_ATTRIBUTE((warn_unused_result)) dberr_t
 #endif /* UNIV_DEBUG_DEDICATED */
 
   ret = os_file_set_size_fast(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);