From 0f4c580d606c11c3aa65d317df2771dee50beeb3 Mon Sep 17 00:00:00 2001 From: Przemyslaw Skibinski Date: Tue, 14 Jun 2022 09:26:10 +0200 Subject: [PATCH] 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::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(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 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 #13 0x3b58b9b in Sql_cmd_create_table::execute(THD*) sql/sql_cmd_ddl_table.cc:319 #14 0x15917c1 in mysql_execute_command(THD*, bool) sql/sql_parse.cc:4417 #15 0x15b086e in mysql_parse(THD*, Parser_state*, bool) sql/sql_parse.cc:5139 #16 0x8efc7fd in Query_log_event::do_apply_event(Relay_log_info const*, char const*, unsigned long) sql/log_event.cc:5295 #17 0x8f7ea48 in Log_event::apply_event(Relay_log_info*) sql/log_event.cc:3882 #18 0x91cb682 in apply_event_and_update_pos sql/rpl_slave.cc:4352 #19 0x9215e69 in exec_relay_log_event sql/rpl_slave.cc:4812 #20 0x9254685 in handle_slave_sql sql/rpl_slave.cc:6912 #21 0xb1913a3 in pfs_spawn_thread storage/perfschema/pfs.cc:2836 #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. --- .../r/doublewrite_multiple_pools.result | 4 ++++ .../innodb/r/innodb_row_log_encryption.result | 4 ++-- .../innodb/t/innodb_row_log_encryption.test | 5 ++--- storage/innobase/buf/buf0flu.cc | 8 ++++--- storage/innobase/fil/fil0fil.cc | 4 ++-- storage/innobase/handler/ha_innodb.cc | 1 + storage/innobase/include/log0recv.h | 7 +++++-- storage/innobase/log/log0online.cc | 21 ++++++++++++------- storage/innobase/log/log0recv.cc | 16 +++++++++----- storage/innobase/row/row0log.cc | 6 ++++-- 10 files changed, 50 insertions(+), 26 deletions(-) diff --git a/mysql-test/suite/innodb/r/doublewrite_multiple_pools.result b/mysql-test/suite/innodb/r/doublewrite_multiple_pools.result index e114fbba1ecf..6bb197346ff8 100644 --- a/mysql-test/suite/innodb/r/doublewrite_multiple_pools.result +++ b/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 diff --git a/mysql-test/suite/innodb/r/innodb_row_log_encryption.result b/mysql-test/suite/innodb/r/innodb_row_log_encryption.result index 18992900543b..0306a9d3598c 100644 --- a/mysql-test/suite/innodb/r/innodb_row_log_encryption.result +++ b/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: CREATE TABLE t1(id INT NOT NULL PRIMARY KEY AUTO_INCREMENT, credit_card VARCHAR(200), private VARCHAR(50)) ENGINE=InnoDB ENCRYPTION='y'; diff --git a/mysql-test/suite/innodb/t/innodb_row_log_encryption.test b/mysql-test/suite/innodb/t/innodb_row_log_encryption.test index b098e0f62578..7892cbb904a3 100644 --- a/mysql-test/suite/innodb/t/innodb_row_log_encryption.test +++ b/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 diff --git a/storage/innobase/buf/buf0flu.cc b/storage/innobase/buf/buf0flu.cc index 18db3007e76b..04cb3e935bb9 100644 --- a/storage/innobase/buf/buf0flu.cc +++ b/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); } } diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc index f20af67e6d62..aa2f39492981 100644 --- a/storage/innobase/fil/fil0fil.cc +++ b/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(); diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index df386987c061..b2c9b733caeb 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -10639,6 +10639,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; } diff --git a/storage/innobase/include/log0recv.h b/storage/innobase/include/log0recv.h index be0ad3affe9b..ffd459b47b62 100644 --- a/storage/innobase/include/log0recv.h +++ b/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 diff --git a/storage/innobase/log/log0online.cc b/storage/innobase/log/log0online.cc index 6bce8ca1af34..f89272d27749 100644 --- a/storage/innobase/log/log0online.cc +++ b/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) { diff --git a/storage/innobase/log/log0recv.cc b/storage/innobase/log/log0recv.cc index ede17d0f3207..f1d354a37fd4 100644 --- a/storage/innobase/log/log0recv.cc +++ b/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); diff --git a/storage/innobase/row/row0log.cc b/storage/innobase/row/row0log.cc index 46b17c8bc1b4..81b88253aa56 100644 --- a/storage/innobase/row/row0log.cc +++ b/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) {