PS-269 (Initial Percona Server 8.0.12 tree) - innobase

1. Fix merge error that broke row_log_online_op by making it write
unencrypted blocks even with encryption enabled

2. Plug a memory leak in log_online_setup_bitmap_file_range introduced by
a rewrite in 8.0 to use my_dir: use my_dirend.

3. Plug a memory leak in log_online_read_init introduced by a rewrite in
8.0 to use my_dir: use my_dirend.

4. create_table_info_t::create_table_def leaked memory in the case
enable_encryption(table) call failed:

worker[5] Sanitizer report from /tmp/results/PS/mysql-test/var/5/log/mysqld.2.err after tests:
 binlog_encryption.binlog_encryption_without_keyring group_replication.gr_change_master_hidden group_replication.gr_server_uuid_matches_group_name group_replication.gr_perfschema_connect_status group_replication.gr_single_primary_and_leader_election_on_error group_replication.gr_without_perfschema rpl.rpl_key_rotation
--------------------------------------------------------------------------
==14131==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 1136 byte(s) in 1 object(s) allocated from:
    #0 0x7fe9233f1602 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x98602)
    #1 0xc692483 in ut_allocator<unsigned char>::allocate(unsigned long, unsigned char const*, unsigned int, bool, bool) storage/innobase/include/ut0new.h:608
    #2 0xc692483 in mem_heap_create_block_func(mem_block_info_t*, unsigned long, unsigned long) storage/innobase/mem/memory.cc:281
    #3 0xb99ff96 in mem_heap_create_func storage/innobase/include/mem0mem.ic:464
    #4 0xbae8604 in create_table_info_t::create_table_def(dd::Table const*) storage/innobase/handler/ha_innodb.cc:10349
    #5 0xbaee018 in create_table_info_t::create_table(dd::Table const*) storage/innobase/handler/ha_innodb.cc:12420
    #6 0xbaf1aba in int innobase_basic_ddl::create_impl<dd::Table>(THD*, char const*, TABLE*, HA_CREATE_INFO*, dd::Table*, bool, bool, bool, unsigned long, unsigned long) storage/innobase/handler/ha_innodb.cc:12805
    #7 0xbaf7e6a in ha_innobase::create(char const*, TABLE*, HA_CREATE_INFO*, dd::Table*) storage/innobase/handler/ha_innodb.cc:13756
    #8 0x2857f7a in ha_create_table(THD*, char const*, char const*, char const*, HA_CREATE_INFO*, List<Create_field> const*, bool, bool, dd::Table*) sql/handler.cc:5156
    #9 0x19d0d9f in rea_create_base_table sql/sql_table.cc:991
    #10 0x19d0d9f in create_table_impl sql/sql_table.cc:7118
    #11 0x19d37cf in mysql_create_table_no_lock(THD*, char const*, char const*, HA_CREATE_INFO*, Alter_info*, unsigned int, bool, bool*, handlerton**) sql/sql_table.cc:7200
    #12 0x19dffb2 in mysql_create_table(THD*, TABLE_LIST*, HA_CREATE_INFO*, Alter_info*) sql/sql_table.cc:7950
    percona#13 0x3b58b9b in Sql_cmd_create_table::execute(THD*) sql/sql_cmd_ddl_table.cc:319
    percona#14 0x15917c1 in mysql_execute_command(THD*, bool) sql/sql_parse.cc:4417
    percona#15 0x15b086e in mysql_parse(THD*, Parser_state*, bool) sql/sql_parse.cc:5139
    percona#16 0x8efc7fd in Query_log_event::do_apply_event(Relay_log_info const*, char const*, unsigned long) sql/log_event.cc:5295
    percona#17 0x8f7ea48 in Log_event::apply_event(Relay_log_info*) sql/log_event.cc:3882
    percona#18 0x91cb682 in apply_event_and_update_pos sql/rpl_slave.cc:4352
    percona#19 0x9215e69 in exec_relay_log_event sql/rpl_slave.cc:4812
    percona#20 0x9254685 in handle_slave_sql sql/rpl_slave.cc:6912
    percona#21 0xb1913a3 in pfs_spawn_thread storage/perfschema/pfs.cc:2836
    percona#22 0x7fe9231436b9 in start_thread (/lib/x86_64-linux-gnu/libpthread.so.0+0x76b9)

Fix by adding the missing mem_heap_free(heap) call.

5. Fix merge error which resulted in a single LRU manager thread being
created as opposed to one per buffer pool instance. At the same time
trivially fix one of the multiple-buffer-pool-instance testcases.

6. Partially fix changed page tracking:
- avoid deadlock on Fil_shard mutex between server shutdown thread and
  changed page tracking by moving the
  Fil_system::wait_for_changed_page_tracker call outside this mutex
  critical section;
- extend recv_read_log_seg with a new argument bool online, which is
  false during recovery and true for changed page tracking reads. In
  function body, use it to guard
  log_background_threads_inactive_validate call (as the background
  threads are active during changed page tracking), and to acquire the
  log_writer mutex, which is not held for the changed page tracking;
- fix MIN_TRACKED_LSN to stop being OS_FILE_LOG_BLOCK_SIZE-too large;
- take last checkpoint LSN to start tracking from, instead of the
  larger of that LSN and MIN_TRACKED_LSN, as the checkpoint LSN is
  always valid at that point;
- strengthen asserts in log_online_add_to_parse_buf.

mysql-test/suite/innodb/r/doublewrite_multiple_pools.result

@@ -31,6 +31,7 @@ where name = 'test/t1' into @space_id;
 # Ensure that dirty pages of table t1 is flushed.
 flush tables t1 for export;
 unlock tables;
+SET GLOBAL innodb_checkpoint_disabled=1;
 begin;
 insert into t1 values (6, repeat('%', 12));
 # Make the first page dirty for table t1
@@ -61,6 +62,7 @@ where name = 'test/t1' into @space_id;
 # Ensure that dirty pages of table t1 is flushed.
 flush tables t1 for export;
 unlock tables;
+SET GLOBAL innodb_checkpoint_disabled=1;
 begin;
 insert into t1 values (6, repeat('%', 12));
 # Make the first page dirty for table t1
@@ -90,6 +92,7 @@ where name = 'test/t1' into @space_id;
 # Ensure that dirty pages of table t1 is flushed.
 flush tables t1 for export;
 unlock tables;
+SET GLOBAL innodb_checkpoint_disabled=1;
 begin;
 insert into t1 values (6, repeat('%', 400));
 # Make the 2nd page dirty for table t1
@@ -119,6 +122,7 @@ where name = 'test/t1' into @space_id;
 # Ensure that dirty pages of table t1 is flushed.
 flush tables t1 for export;
 unlock tables;
+SET GLOBAL innodb_checkpoint_disabled=1;
 begin;
 insert into t1 values (6, repeat('%', 400));
 # Make the 2nd page dirty for table t1

mysql-test/suite/innodb/r/innodb_row_log_encryption.result

@@ -1,5 +1,5 @@
-call mtr.add_suppression("\\[ERROR\\] Function 'keyring_file' already exists");
-call mtr.add_suppression("\\[ERROR\\] Couldn't load plugin named 'keyring_file' with soname 'keyring_file.*'.");
+call mtr.add_suppression("Function 'keyring_file' already exists");
+call mtr.add_suppression("Couldn't load plugin named 'keyring_file' with soname 'keyring_file.*'.");
 call mtr.add_suppression("Plugin keyring_file reported");
 # restart:<hidden args>
 CREATE TABLE t1(id INT NOT NULL PRIMARY KEY AUTO_INCREMENT, credit_card VARCHAR(200), private VARCHAR(50)) ENGINE=InnoDB ENCRYPTION='y';

mysql-test/suite/innodb/t/innodb_row_log_encryption.test

@@ -1,6 +1,5 @@
-
-call mtr.add_suppression("\\[ERROR\\] Function 'keyring_file' already exists");
-call mtr.add_suppression("\\[ERROR\\] Couldn't load plugin named 'keyring_file' with soname 'keyring_file.*'.");
+call mtr.add_suppression("Function 'keyring_file' already exists");
+call mtr.add_suppression("Couldn't load plugin named 'keyring_file' with soname 'keyring_file.*'.");
 call mtr.add_suppression("Plugin keyring_file reported");
 
 --let $keyring_restart_param=restart: --early-plugin-load="keyring_file=$KEYRING_PLUGIN" --keyring_file_data=$MYSQL_TMP_DIR/mysecret_keyring $KEYRING_PLUGIN_OPT --innodb-sort-buffer-size=64k --innodb_encrypt_online_alter_logs=ON

storage/innobase/buf/buf0flu.cc

@@ -2602,11 +2602,13 @@ void buf_flush_page_cleaner_init(size_t n_page_cleaners) {
   os_thread_create(page_flush_coordinator_thread_key,
                    buf_flush_page_coordinator_thread, n_page_cleaners);
 
-  os_thread_create(buf_lru_manager_thread_key, buf_lru_manager_thread);
+  for (decltype(srv_buf_pool_instances) i = 0; i < srv_buf_pool_instances; i++)
+    os_thread_create(buf_lru_manager_thread_key, buf_lru_manager_thread);
 
   /* Make sure page cleaner and LRU managers are active. */
-
-  while (!buf_page_cleaner_is_active) {
+  while (!buf_page_cleaner_is_active ||
+         buf_lru_manager_running_threads.load(std::memory_order_relaxed) <
+             srv_buf_pool_instances) {
     os_thread_sleep(10000);
   }
 }

storage/innobase/fil/fil0fil.cc

@@ -3383,8 +3383,6 @@ void Fil_system::wait_for_changed_page_tracker() noexcept {
 void Fil_shard::close_all_files() {
   ut_ad(mutex_owned());
 
-  Fil_system::wait_for_changed_page_tracker();
-
   auto end = m_spaces.end();
 
   for (auto it = m_spaces.begin(); it != end; it = m_spaces.erase(it)) {
@@ -3414,6 +3412,8 @@ void Fil_shard::close_all_files() {
 
 /** Close all open files. */
 void Fil_system::close_all_files() {
+  Fil_system::wait_for_changed_page_tracker();
+
   for (auto shard : m_shards) {
     shard->mutex_acquire();
 

storage/innobase/handler/ha_innodb.cc

@@ -10637,6 +10637,7 @@ inline MY_ATTRIBUTE((warn_unused_result)) int create_table_info_t::
   err = enable_encryption(table);
   if (err != DB_SUCCESS) {
     dict_mem_table_free(table);
+    mem_heap_free(heap);
     goto error_ret;
   }
 

storage/innobase/include/log0recv.h

@@ -68,8 +68,11 @@ lsn_t recv_calc_lsn_on_data_add(
 @param[in,out]	log		redo log
 @param[in,out]	buf		buffer where to read
 @param[in]	start_lsn	read area start
-@param[in]	end_lsn		read area end */
-void recv_read_log_seg(log_t &log, byte *buf, lsn_t start_lsn, lsn_t end_lsn);
+@param[in]	end_lsn		read area end
+@param[in]	online		whether the read is for the changed page
+                                tracking */
+void recv_read_log_seg(log_t &log, byte *buf, lsn_t start_lsn, lsn_t end_lsn,
+                       bool online);
 
 /** Tries to parse a single log record.
 @param[out]	type		log record type

storage/innobase/log/log0online.cc

@@ -102,10 +102,10 @@ name, the 2nd tag is the stem, the 3rd tag is a file sequence number, the 4th
 tag is the start LSN for the file. */
 static const constexpr char *bmp_file_name_template = "%s%s%lu_" LSN_PF ".xdb";
 
-/* On server startup with empty database srv_start_lsn == 0, in
-which case the first LSN of actual log records will be this. */
+/** On server startup with empty database the first LSN of actual log records
+will be this. */
 static const constexpr auto MIN_TRACKED_LSN =
-    LOG_START_LSN + OS_FILE_LOG_BLOCK_SIZE + LOG_BLOCK_HDR_SIZE;
+    LOG_START_LSN + LOG_BLOCK_HDR_SIZE;
 
 /* Tests if num bit of bitmap is set */
 #define IS_BIT_SET(bitmap, num) \
@@ -566,6 +566,7 @@ that's the cwd */
       log_bmp_sys->out.name[FN_REFLEN - 1] = '\0';
     }
   }
+  my_dirend(bitmap_dir);
 
   if (!log_bmp_sys->out_seq_num) {
     log_bmp_sys->out_seq_num = 1;
@@ -581,8 +582,7 @@ that's the cwd */
       innodb_bmp_file_key, log_bmp_sys->out.name, OS_FILE_OPEN,
       OS_FILE_READ_WRITE, srv_read_only_mode, &success);
 
-  const lsn_t tracking_start_lsn =
-      std::max(log_sys->last_checkpoint_lsn.load(), MIN_TRACKED_LSN);
+  const auto tracking_start_lsn = log_sys->last_checkpoint_lsn.load();
   if (!success) {
     /* New file, tracking from scratch */
     if (!log_online_start_bitmap_file()) {
@@ -789,6 +789,10 @@ static void log_online_add_to_parse_buf(
                                    skip */
     noexcept {
   ut_ad(mutex_own(&log_bmp_sys_mutex));
+  // Do not skip into middle of the header
+  ut_ad(!skip_len || skip_len >= LOG_BLOCK_HDR_SIZE);
+  // Do not call this if the whole block must be skipped
+  ut_ad(skip_len < OS_FILE_LOG_BLOCK_SIZE - LOG_BLOCK_TRL_SIZE);
 
   const ulint start_offset = skip_len ? skip_len : LOG_BLOCK_HDR_SIZE;
   const ulint end_offset = (data_len == OS_FILE_LOG_BLOCK_SIZE)
@@ -842,7 +846,7 @@ static bool log_online_follow_log_seg(
       log_bmp_sys->read_buf + (block_end_lsn - block_start_lsn);
 
   recv_read_log_seg(*log_sys, log_bmp_sys->read_buf, block_start_lsn,
-                    block_end_lsn);
+                    block_end_lsn, true);
 
   while (log_block < log_block_end &&
          log_bmp_sys->next_parse_lsn < log_bmp_sys->end_lsn) {
@@ -1050,7 +1054,7 @@ bool log_online_follow_redo_log(void) {
   }
 
   /* Grab the LSN of the last checkpoint, we will parse up to it */
-  log_bmp_sys->end_lsn = log_sys->last_checkpoint_lsn;
+  log_bmp_sys->end_lsn = log_get_checkpoint_lsn(*log_sys);
 
   if (log_bmp_sys->end_lsn == log_bmp_sys->start_lsn) {
     mutex_exit(&log_bmp_sys_mutex);
@@ -1146,6 +1150,7 @@ it, replacing another such file */
       }
     }
   }
+  my_dirend(bitmap_dir);
 
   if (first_file_seq_num == ULONG_MAX && last_file_seq_num == 0) {
     bitmap_files->count = 0;
@@ -1181,6 +1186,7 @@ it, replacing another such file */
     const size_t array_pos = file_seq_num - first_file_seq_num;
     if (UNIV_UNLIKELY(array_pos >= bitmap_files->count)) {
       log_online_diagnose_inconsistent_dir(bitmap_files);
+      my_dirend(bitmap_dir);
       return false;
     }
 
@@ -1192,6 +1198,7 @@ it, replacing another such file */
       bitmap_files->files[array_pos].start_lsn = file_start_lsn;
     }
   }
+  my_dirend(bitmap_dir);
 
   if (!bitmap_files->files[0].seq_num ||
       bitmap_files->files[0].seq_num != first_file_seq_num) {

storage/innobase/log/log0recv.cc

@@ -3205,14 +3205,20 @@ bool meb_scan_log_recs(
 /** Reads a specified log segment to a buffer.
 @param[in,out]	log		redo log
 @param[in,out]	buf		buffer where to read
-@param[in]	start_lsn	read area start */
-void recv_read_log_seg(log_t &log, byte *buf, lsn_t start_lsn, lsn_t end_lsn) {
-  log_background_threads_inactive_validate(log);
+@param[in]	start_lsn	read area start
+@param[in]	end_lsn		read area end
+@param[in]	online		whether the read is for the changed page
+                                tracking */
+void recv_read_log_seg(log_t &log, byte *buf, lsn_t start_lsn, lsn_t end_lsn,
+                       bool online) {
+  if (!online) log_background_threads_inactive_validate(log);
 
   do {
     lsn_t source_offset;
 
+    if (online) log_writer_mutex_enter(log);
     source_offset = log_files_real_offset_for_lsn(log, start_lsn);
+    if (online) log_writer_mutex_exit(log);
 
     ut_a(end_lsn - start_lsn <= ULINT_MAX);
 
@@ -3302,7 +3308,7 @@ static void recv_recovery_begin(log_t &log, lsn_t *contiguous_lsn) {
   while (!finished) {
     lsn_t end_lsn = start_lsn + RECV_SCAN_SIZE;
 
-    recv_read_log_seg(log, log.buf, start_lsn, end_lsn);
+    recv_read_log_seg(log, log.buf, start_lsn, end_lsn, false);
 
     finished = recv_scan_log_recs(log, max_mem, log.buf, RECV_SCAN_SIZE,
                                   checkpoint_lsn, start_lsn, contiguous_lsn,
@@ -3534,7 +3540,7 @@ dberr_t recv_recovery_from_checkpoint_start(log_t &log, lsn_t flush_lsn) {
   if (start_lsn < end_lsn) {
     ut_a(start_lsn % log.buf_size + OS_FILE_LOG_BLOCK_SIZE <= log.buf_size);
 
-    recv_read_log_seg(log, recv_sys->last_block, start_lsn, end_lsn);
+    recv_read_log_seg(log, recv_sys->last_block, start_lsn, end_lsn, false);
 
     memcpy(log.buf + start_lsn % log.buf_size, recv_sys->last_block,
            OS_FILE_LOG_BLOCK_SIZE);

storage/innobase/row/row0log.cc

@@ -479,6 +479,7 @@ void row_log_online_op(
     IORequest request(IORequest::WRITE);
     const os_offset_t byte_offset =
         (os_offset_t)log->tail.blocks * srv_sort_buf_size;
+    byte *buf = log->tail.block;
 
     if (byte_offset + srv_sort_buf_size >= srv_online_max_size) {
       goto write_failed;
@@ -509,10 +510,11 @@ void row_log_online_op(
       }
 
       srv_stats.n_rowlog_blocks_encrypted.inc();
+      buf = log->crypt_tail;
     }
 
-    err = os_file_write_int_fd(request, "(modification log)", log->fd,
-                               log->tail.block, byte_offset, srv_sort_buf_size);
+    err = os_file_write_int_fd(request, "(modification log)", log->fd, buf,
+                               byte_offset, srv_sort_buf_size);
 
     log->tail.blocks++;
     if (err != DB_SUCCESS) {