PS-3410 : LP #1570114: Long running ALTER TABLE ADD INDEX causes sema…

…phore 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.

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 = 100;
+SET GLOBAL DEBUG = '-d, innodb_bulk_load_compress_sleep';
+SET GLOBAL innodb_semaphore_wait_timeout_debug = 600;
+DROP PROCEDURE populate_t1;

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

@@ -0,0 +1,69 @@
+--source include/have_debug.inc
+--source include/have_debug_sync.inc
+--source include/have_innodb.inc
+
+--let $orig_fill_factor = `SELECT @@innodb_fill_factor`
+SET GLOBAL innodb_fill_factor = 10;
+
+--let $orig_sem_timeout = `SELECT @@innodb_semaphore_wait_timeout_debug`
+SET GLOBAL innodb_semaphore_wait_timeout_debug = 120;
+
+# This statement helps to run ALTER for long time without actually
+# creating a very big table
+SET GLOBAL DEBUG = '+d, innodb_bulk_load_compress_sleep';
+
+--source include/count_sessions.inc
+
+connect (con1,localhost,root,,);
+
+CREATE TABLE t1(
+  class   INT,
+  id      INT,
+  title   VARCHAR(100),
+ title2  VARCHAR(100)
+) ENGINE=InnoDB ROW_FORMAT=COMPRESSED KEY_BLOCK_SIZE=4;
+
+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 con1
+SET DEBUG_SYNC = 'bulk_load_insert SIGNAL alter_started WAIT_FOR resume_alter';
+--send CREATE INDEX idx_title ON t1(title, title2);
+
+--connection default
+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 con1
+--reap
+
+--connection default
+--reap
+
+--disconnect con1
+
+DROP TABLE t1;
+
+SET DEBUG_SYNC = 'RESET';
+
+eval SET GLOBAL innodb_fill_factor = $orig_fill_factor;
+SET GLOBAL DEBUG = '-d, innodb_bulk_load_compress_sleep';
+eval SET GLOBAL innodb_semaphore_wait_timeout_debug = $orig_sem_timeout;
+DROP PROCEDURE populate_t1;
+--source include/wait_until_count_sessions.inc

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"),

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

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;

storage/innobase/btr/btr0bulk.cc

@@ -50,7 +50,9 @@ PageBulk::init()
 	mtr = static_cast<mtr_t*>(
 		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;

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));

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),