From b11e34171dd8d8387ba56ec53cbb98156f2c2173 Mon Sep 17 00:00:00 2001 From: Satya Bodapati Date: Tue, 16 Apr 2019 10:13:57 +0530 Subject: [PATCH] PS-3410 : LP #1570114: Long running ALTER TABLE ADD INDEX causes semaphore wait > 600 assertion Problem: -------- A long running ALTER TABLE ADD INDEX with concurrent inserts causes sempahore waits and eventually crashes the server. To see this problem you need to have 1. A table with lots of data. Add index should take significant time to create many pages 2. Compressed table. This is becuase CPU is spent on compress() with mtr already latching index->lock More time spent by mtr, more waits by the INSERT. Helps in crash. 3. Concurrent inserts when ALTER is running. The inserts should happen specifically after the read phase of ALTER and after Bulk load index build (bottump build) started. The entire bulkload process latches the index->lock X mode for the whole duration of bottom up build of index. The index->lock is held across mtrs (because many pages are created during index build). An example is this: Page1 mtr latches index->lock X mode, when page is full, a sibling page is created. The sibling Page 2 (mtr) also acquires index->lock X mode. Recursive X latching is allowed by same thread. Now Page 1 mtr commits but index->lock is still held by Page 2. Now when page 2 is full, another sibling page is created. Sibling Page 3 now acquires index->lock X mode. Page 2 mtr commits.. This goes on and on. Also happens with Pages at non-root levels. Essentially the time index->lock is held is equally proportional to number of pages/mtrs created. And compress tables helps in making mtr take a bit more time in doing compress() and duration of each mtr is higher with compressed tables. At this stage, a concurrent INSERT comes and since there is concurrent DDL and the index is uncommited, this insert should go to online ALTER log. It tries to acquire index->lock in S mode. Bulk load index already took index->lock X mode and is not going to release it until is over. INSERT thread keeps on waiting, and when the wait crosses 600 seconds to acquire index->lock, it will crash. Fix: ---- INSERT thread acquires index->lock to check the index online status. During the bulk load index build, there is no concurrent insert or read. So there is no need to acquire index->lock at all. Bulk load index build is also used to create indexes in table rebuild cases. For example DROP COLUMN, ADD COLUMN. The indexes on intermediate table (#sql-ib..) are built using bulk load insert. A concurrent DMLs at this stage do not acquire index->lock. So acquiring index->lock on the intermediate table, which is not visible to anyone else doesn't block concurrent DMLs. Ideally we can try to remove all index->lock X acquisitions in bulk load index build path. We play *safe* and remove acquisitions only incase of uncommited indexes. The other path (bulk load used during rebuild) is not affected anyway. --- .../innodb/r/percona_bulk_load_insert.result | 30 +++++++++ .../innodb/t/percona_bulk_load_insert.test | 65 +++++++++++++++++++ .../suite/perfschema/t/show_sanity.test | 1 + ..._semaphore_wait_timeout_debug_basic.result | 36 ++++++++++ ...db_semaphore_wait_timeout_debug_basic.test | 30 +++++++++ storage/innobase/btr/btr0bulk.cc | 16 ++++- storage/innobase/btr/btr0cur.cc | 3 +- storage/innobase/handler/ha_innodb.cc | 8 +++ 8 files changed, 186 insertions(+), 3 deletions(-) create mode 100644 mysql-test/suite/innodb/r/percona_bulk_load_insert.result create mode 100644 mysql-test/suite/innodb/t/percona_bulk_load_insert.test create mode 100644 mysql-test/suite/sys_vars/r/innodb_semaphore_wait_timeout_debug_basic.result create mode 100644 mysql-test/suite/sys_vars/t/innodb_semaphore_wait_timeout_debug_basic.test diff --git a/mysql-test/suite/innodb/r/percona_bulk_load_insert.result b/mysql-test/suite/innodb/r/percona_bulk_load_insert.result new file mode 100644 index 000000000000..4032231dc635 --- /dev/null +++ b/mysql-test/suite/innodb/r/percona_bulk_load_insert.result @@ -0,0 +1,30 @@ +SET GLOBAL innodb_fill_factor = 10; +SET GLOBAL innodb_semaphore_wait_timeout_debug = 120; +SET GLOBAL DEBUG = '+d, innodb_bulk_load_compress_sleep'; +CREATE TABLE t1( +class INT, +id INT, +title VARCHAR(100), +title2 VARCHAR(100) +) ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4; +CREATE PROCEDURE populate_t1() +BEGIN +DECLARE i int DEFAULT 1; +START TRANSACTION; +WHILE (i <= 30000) DO +INSERT INTO t1 VALUES (i, i, uuid(), uuid()); +SET i = i + 1; +END WHILE; +COMMIT; +END| +SET DEBUG_SYNC = 'bulk_load_insert SIGNAL alter_started WAIT_FOR resume_alter'; +CREATE INDEX idx_title ON t1(title, title2);; +SET DEBUG_SYNC = 'now WAIT_FOR alter_started'; +SET DEBUG_SYNC = 'row_ins_sec_index_enter SIGNAL resume_alter'; +INSERT INTO t1 VALUES (32000, 32000, uuid(), uuid());; +DROP TABLE t1; +SET DEBUG_SYNC = 'RESET'; +SET GLOBAL innodb_fill_factor = default; +SET GLOBAL DEBUG = '-d, innodb_bulk_load_compress_sleep'; +SET GLOBAL innodb_semaphore_wait_timeout_debug = default; +DROP PROCEDURE populate_t1; diff --git a/mysql-test/suite/innodb/t/percona_bulk_load_insert.test b/mysql-test/suite/innodb/t/percona_bulk_load_insert.test new file mode 100644 index 000000000000..8f3641279337 --- /dev/null +++ b/mysql-test/suite/innodb/t/percona_bulk_load_insert.test @@ -0,0 +1,65 @@ +--source include/have_debug.inc +--source include/have_debug_sync.inc + +SET GLOBAL innodb_fill_factor = 10; +SET GLOBAL innodb_semaphore_wait_timeout_debug = 120; +SET GLOBAL DEBUG = '+d, innodb_bulk_load_compress_sleep'; +--source include/count_sessions.inc + +connect (con1,localhost,root,,); +connect (con2,localhost,root,,); + +CREATE TABLE t1( + class INT, + id INT, + title VARCHAR(100), + title2 VARCHAR(100) +) ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4; + +# Create Insert Procedure +DELIMITER |; +CREATE PROCEDURE populate_t1() +BEGIN + DECLARE i int DEFAULT 1; + + START TRANSACTION; + WHILE (i <= 30000) DO + INSERT INTO t1 VALUES (i, i, uuid(), uuid()); + SET i = i + 1; + END WHILE; + COMMIT; +END| +DELIMITER ;| + +--disable_query_log +CALL populate_t1(); +--enable_query_log + +--connection con2 +SET DEBUG_SYNC = 'bulk_load_insert SIGNAL alter_started WAIT_FOR resume_alter'; +--send CREATE INDEX idx_title ON t1(title, title2); + +--connection con1 +SET DEBUG_SYNC = 'now WAIT_FOR alter_started'; +SET DEBUG_SYNC = 'row_ins_sec_index_enter SIGNAL resume_alter'; +--send INSERT INTO t1 VALUES (32000, 32000, uuid(), uuid()); + +--connection con2 +--reap + +--connection con1 +--reap + +--connection default +--disconnect con1 +--disconnect con2 + +DROP TABLE t1; + +SET DEBUG_SYNC = 'RESET'; + +SET GLOBAL innodb_fill_factor = default; +SET GLOBAL DEBUG = '-d, innodb_bulk_load_compress_sleep'; +SET GLOBAL innodb_semaphore_wait_timeout_debug = default; +DROP PROCEDURE populate_t1; +--source include/wait_until_count_sessions.inc diff --git a/mysql-test/suite/perfschema/t/show_sanity.test b/mysql-test/suite/perfschema/t/show_sanity.test index 265ef4dbfc4c..6728504d9903 100644 --- a/mysql-test/suite/perfschema/t/show_sanity.test +++ b/mysql-test/suite/perfschema/t/show_sanity.test @@ -531,6 +531,7 @@ insert into test.sanity values ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SCHED_PRIORITY_IO"), ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SCHED_PRIORITY_MASTER"), ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SCHED_PRIORITY_PURGE"), + ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SEMAPHORE_WAIT_TIMEOUT_DEBUG"), ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SHOW_LOCKS_HELD"), ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SHOW_VERBOSE_LOCKS"), ("JUNK: GLOBAL-ONLY", "I_S.SESSION_VARIABLES", "INNODB_SORT_BUFFER_SIZE"), diff --git a/mysql-test/suite/sys_vars/r/innodb_semaphore_wait_timeout_debug_basic.result b/mysql-test/suite/sys_vars/r/innodb_semaphore_wait_timeout_debug_basic.result new file mode 100644 index 000000000000..4c6d2511cca7 --- /dev/null +++ b/mysql-test/suite/sys_vars/r/innodb_semaphore_wait_timeout_debug_basic.result @@ -0,0 +1,36 @@ +# +# Basic test for innodb_semaphore_wait_timeout_debug +# +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +600 +set global innodb_semaphore_wait_timeout_debug = 10; +Warnings: +Warning 1292 Truncated incorrect innodb_semaphore_wait_timeout_de value: '10' +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +100 +SET GLOBAL innodb_semaphore_wait_timeout_debug = 200; +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +200 +SET GLOBAL innodb_semaphore_wait_timeout_debug = dummy; +ERROR 42000: Incorrect argument type to variable 'innodb_semaphore_wait_timeout_debug' +SET innodb_semaphore_wait_timeout_debug = 100; +ERROR HY000: Variable 'innodb_semaphore_wait_timeout_debug' is a GLOBAL variable and should be set with SET GLOBAL +SET GLOBAL innodb_semaphore_wait_timeout_debug = 6000; +Warnings: +Warning 1292 Truncated incorrect innodb_semaphore_wait_timeout_de value: '6000' +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +600 +SET GLOBAL innodb_semaphore_wait_timeout_debug = -1; +Warnings: +Warning 1292 Truncated incorrect innodb_semaphore_wait_timeout_de value: '-1' +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +100 +SET GLOBAL innodb_semaphore_wait_timeout_debug = default; +SELECT @@global.innodb_semaphore_wait_timeout_debug; +@@global.innodb_semaphore_wait_timeout_debug +600 diff --git a/mysql-test/suite/sys_vars/t/innodb_semaphore_wait_timeout_debug_basic.test b/mysql-test/suite/sys_vars/t/innodb_semaphore_wait_timeout_debug_basic.test new file mode 100644 index 000000000000..0f89b187290c --- /dev/null +++ b/mysql-test/suite/sys_vars/t/innodb_semaphore_wait_timeout_debug_basic.test @@ -0,0 +1,30 @@ +--echo # +--echo # Basic test for innodb_semaphore_wait_timeout_debug +--echo # + +--source include/have_innodb.inc +# The config variable is a debug variable +--source include/have_debug.inc + +SELECT @@global.innodb_semaphore_wait_timeout_debug; + +set global innodb_semaphore_wait_timeout_debug = 10; +SELECT @@global.innodb_semaphore_wait_timeout_debug; + +SET GLOBAL innodb_semaphore_wait_timeout_debug = 200; +SELECT @@global.innodb_semaphore_wait_timeout_debug; + +--error ER_WRONG_TYPE_FOR_VAR +SET GLOBAL innodb_semaphore_wait_timeout_debug = dummy; + +--error ER_GLOBAL_VARIABLE +SET innodb_semaphore_wait_timeout_debug = 100; + +SET GLOBAL innodb_semaphore_wait_timeout_debug = 6000; +SELECT @@global.innodb_semaphore_wait_timeout_debug; + +SET GLOBAL innodb_semaphore_wait_timeout_debug = -1; +SELECT @@global.innodb_semaphore_wait_timeout_debug; + +SET GLOBAL innodb_semaphore_wait_timeout_debug = default; +SELECT @@global.innodb_semaphore_wait_timeout_debug; diff --git a/storage/innobase/btr/btr0bulk.cc b/storage/innobase/btr/btr0bulk.cc index 5b89b558c044..b5070cbd4d86 100644 --- a/storage/innobase/btr/btr0bulk.cc +++ b/storage/innobase/btr/btr0bulk.cc @@ -50,7 +50,9 @@ PageBulk::init() mtr = static_cast( mem_heap_alloc(m_heap, sizeof(mtr_t))); mtr_start(mtr); - mtr_x_lock(dict_index_get_lock(m_index), mtr); + if (m_index->is_committed()) { + mtr_x_lock(dict_index_get_lock(m_index), mtr); + } mtr_set_log_mode(mtr, MTR_LOG_NO_REDO); mtr_set_flush_observer(mtr, m_flush_observer); @@ -333,6 +335,10 @@ PageBulk::compress() { ut_ad(m_page_zip != NULL); + DBUG_EXECUTE_IF("innodb_bulk_load_compress_sleep", + os_thread_sleep(1000000); + ); + return(page_zip_compress(m_page_zip, m_page, m_index, page_zip_level, NULL, m_mtr)); } @@ -604,7 +610,9 @@ PageBulk::latch() ibool ret; mtr_start(m_mtr); - mtr_x_lock(dict_index_get_lock(m_index), m_mtr); + if (m_index->is_committed()) { + mtr_x_lock(dict_index_get_lock(m_index), m_mtr); + } mtr_set_log_mode(m_mtr, MTR_LOG_NO_REDO); mtr_set_flush_observer(m_mtr, m_flush_observer); @@ -791,6 +799,8 @@ BtrBulk::insert( return(err); } + DEBUG_SYNC_C("bulk_load_insert"); + m_page_bulks->push_back(new_page_bulk); ut_ad(level + 1 == m_page_bulks->size()); m_root_level = level; @@ -884,6 +894,8 @@ BtrBulk::insert( offsets = rec_get_offsets(rec, m_index, offsets, ULINT_UNDEFINED, &(page_bulk->m_heap)); + DBUG_EXECUTE_IF("ib_bulk_sleep", sleep(2);); + page_bulk->insert(rec, offsets); if (big_rec != NULL) { diff --git a/storage/innobase/btr/btr0cur.cc b/storage/innobase/btr/btr0cur.cc index 92f4c41803d7..93177d5a2070 100644 --- a/storage/innobase/btr/btr0cur.cc +++ b/storage/innobase/btr/btr0cur.cc @@ -7018,7 +7018,8 @@ btr_store_big_rec_extern_fields( ut_ad(mtr_memo_contains_flagged(btr_mtr, dict_index_get_lock(index), MTR_MEMO_X_LOCK | MTR_MEMO_SX_LOCK) - || dict_table_is_intrinsic(index->table)); + || dict_table_is_intrinsic(index->table) + || !index->is_committed()); ut_ad(mtr_is_block_fix( btr_mtr, rec_block, MTR_MEMO_PAGE_X_FIX, index->table)); ut_ad(buf_block_get_frame(rec_block) == page_align(rec)); diff --git a/storage/innobase/handler/ha_innodb.cc b/storage/innobase/handler/ha_innodb.cc index b1b4a08f6a23..972364d66f24 100644 --- a/storage/innobase/handler/ha_innodb.cc +++ b/storage/innobase/handler/ha_innodb.cc @@ -21562,6 +21562,13 @@ static MYSQL_SYSVAR_UINT(merge_threshold_set_all_debug, " cache by the specified value dynamically, at the time.", NULL, innodb_merge_threshold_set_all_debug_update, DICT_INDEX_MERGE_THRESHOLD_DEFAULT, 1, 50, 0); + +static MYSQL_SYSVAR_ULONG(semaphore_wait_timeout_debug, + srv_fatal_semaphore_wait_threshold, + PLUGIN_VAR_RQCMDARG, + "Number of seconds that a semaphore can be held. If semaphore wait crosses" + "this value, server will crash", NULL, NULL, 600, 100, 600, 0); + #endif /* UNIV_DEBUG */ static MYSQL_SYSVAR_ULONG(purge_batch_size, srv_purge_batch_size, @@ -22844,6 +22851,7 @@ static struct st_mysql_sys_var* innobase_system_variables[]= { MYSQL_SYSVAR(buf_flush_list_now), MYSQL_SYSVAR(track_redo_log_now), MYSQL_SYSVAR(merge_threshold_set_all_debug), + MYSQL_SYSVAR(semaphore_wait_timeout_debug), #endif /* UNIV_DEBUG */ #if defined UNIV_DEBUG || defined UNIV_PERF_DEBUG MYSQL_SYSVAR(page_hash_locks),