[MDEV-16124] fil_rename_tablespace() times out and crashes server during table-rebuilding ALTER TABLE Created: 2018-05-09  Updated: 2022-08-10  Resolved: 2018-06-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB
Affects Version/s: 10.0, 10.1, 10.2.14, 10.2, 10.3
Fix Version/s: 10.0.36, 10.1.34, 10.2.16, 10.3.8

Type: Bug Priority: Major
Reporter: Steve Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: upstream

Attachments: File common.cnf     Text File crash.log     Text File engine_status.log    
Issue Links:
Relates
relates to MDEV-18717 Server crash when trying to alter add... Closed

 Description   

We are getting periodic crashes on our staging server, whilst adding a column and an index. to a table. There are about 200 databases in the server and these are updated to our latest development schemas nightly ready for testing. We will typically get a crash every other day or so. The database that fails varies, but each typically has several hundred thousand rows. The table update that triggers the crash is always:

 ALTER TABLE order_line_items
 
        ADD COLUMN `is_bundle_parent` tinyint(1) NOT NULL default 0,
 
        ADD INDEX `index_order_line_items_on_is_bundle_parent` (`is_bundle_parent`)

Immediately before this alter table we update pretty much all the rows the table. which I suspect may be relevant,

UPDATE order_line_items SET bundle_line_item_id=id WHERE bundle_line_item_id IS NULL

In the mysql error log we see:

2018-05-08 22:43:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 1000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:43:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 2000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:43:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 3000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:44:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 4000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:44:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 5000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:44:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 6000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:45:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 7000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:45:20 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 8000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:45:40 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 9000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:46:00 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 10000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:46:21 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 11000 times. There are either pending IOs or flushes or the file is being extended.

followed by

--Thread 140184803284736 has waited at row0purge.cc line 853 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
 
a writer (thread id 140184283293440) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file row0purge.cc line 853
 
Last time write locked in file handler0alter.cc line 8546
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184278025984 has waited at dict0dict.cc line 1160 for 116.00 seconds the semaphore:
 
Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
 
 
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184736397056 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
 
a writer (thread id 140184744789760) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file ibuf0ibuf.cc line 4578
 
Last time write locked in file mtr0mtr.ic line 147
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184728004352 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
 
a writer (thread id 140184744789760) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file ibuf0ibuf.cc line 4578
 
Last time write locked in file mtr0mtr.ic line 147
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184803284736 has waited at row0purge.cc line 853 for 241.00 seconds the semaphore:
 
S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
 
a writer (thread id 140184283293440) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file row0purge.cc line 853
 
Last time write locked in file handler0alter.cc line 8546
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184783165184 has waited at row0mysql.cc line 1780 for 240.00 seconds the semaphore:
 
S-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
 
a writer (thread id 140184283293440) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file row0purge.cc line 853
 
Last time write locked in file handler0alter.cc line 8546
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184270636800 has waited at dict0dict.cc line 1160 for 233.00 seconds the semaphore:
 
Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
 
 
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184853640960 has waited at srv0srv.cc line 2089 for 240.00 seconds the semaphore:
 
X-lock on RW-latch at 0x563589733d10 created in file dict0dict.cc line 1107
 
a writer (thread id 140184283293440) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file row0purge.cc line 853
 
Last time write locked in file handler0alter.cc line 8546
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184753182464 has waited at ibuf0ibuf.cc line 4578 for 240.00 seconds the semaphore:
 
S-lock on RW-latch at 0x7f805f7eaf48 created in file buf0buf.cc line 1471
 
a writer (thread id 140184744789760) has reserved it in mode  exclusive
 
number of readers 0, waiters flag 1, lock_word: 0
 
Last time read locked in file ibuf0ibuf.cc line 4578
 
Last time write locked in file mtr0mtr.ic line 147
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184744789760 has waited at mtr0mtr.ic line 147 for 240.00 seconds the semaphore:
 
X-lock on RW-latch at 0x7f805f8749d8 created in file buf0buf.cc line 1471
 
a writer (thread id 0) has reserved it in mode  SX
 
number of readers 0, waiters flag 1, lock_word: 10000000
 
Last time read locked in file ibuf0ibuf.cc line 4578
 
Last time write locked in file buf0flu.cc line 1213
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184820070144 has waited at dict0stats_bg.cc line 341 for 235.00 seconds the semaphore:
 
Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2
 
 
 
2018-05-08 22:46:40 140184836855552 [Note] InnoDB: A semaphore wait:
 
--Thread 140184648525568 has waited at dict0dict.cc line 1160 for 35.00 seconds the semaphore:
 
Mutex at 0x563589733d90, Mutex DICT_SYS created dict0dict.cc:1096, lock var 2

The engine innodb status is the dumped. This is attached.

We have experimented with setting the following, but this has has no affect.

innodb_purge_threads           = 1
 
innodb_adaptive_hash_index_parts = 1



 Comments   
Comment by Steve [ 2018-05-09 ]

The server crash occurs several minutes later:

InnoDB: Pending reads 0, writes 0
 
2018-05-08 22:51:02 140184283293440 [Warning] InnoDB: Cannot rename file ./private_104550_production/order_line_items.ibd (space id 51213308), retried 25000 times. There are either pending IOs or flushes or the file is being extended.
 
2018-05-08 22:51:02 0x7f7f3268a700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.14/storage/innobase/handler/handler0alter.cc line 7890
 
InnoDB: Failing assertion: error == DB_SUCCESS
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/
 
InnoDB: about forcing recovery.

Crash log attached.

Comment by Elena Stepanova [ 2018-06-01 ]

Thanks for the report.

Test case from https://bugs.mysql.com/bug.php?id=84762 (with minor adjustments)

--source include/have_innodb.inc
 
SET SESSION debug_dbug="+d,fil_rename_tablespace_failure_1";
 
CREATE TABLE t1(id INT key,txt text not null,unique index txt_index (txt (1))) ENGINE=InnoDB;
 
alter table test.t1 add column b int first;
 
 
 
# Cleanup
 
DROP TABLE t1;

(first modifier was added to make it also fail on 10.3).

10.0 a61724a3ca1

 
180601 18:58:46 [ERROR] InnoDB: Cannot find space id 4 in the tablespace memory cache, though the table 'test/t1' in a rename operation should have that id.
 
2018-06-01 18:58:46 7fa384596700  InnoDB: Assertion failure in thread 140340276848384 in file handler0alter.cc line 5211
 
InnoDB: Failing assertion: error == DB_SUCCESS
 
 
 
#5  0x00007fa382550448 in __GI_abort () at abort.c:89
 
#6  0x00007fa37af6d505 in commit_cache_rebuild (ctx=0x7fa36e5a59b0) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:5211
 
#7  0x00007fa37af6b076 in ha_innodb::commit_inplace_alter_table (this=0x7fa36e47e888, altered_table=0x7fa36e611070, ha_alter_info=0x7fa384593260, commit=true) at /data/src/10.0/storage/innobase/handler/handler0alter.cc:6002
 
#8  0x0000000000840423 in handler::ha_commit_inplace_alter_table (this=0x7fa36e47e888, altered_table=0x7fa36e611070, ha_alter_info=0x7fa384593260, commit=true) at /data/src/10.0/sql/handler.cc:4228
 
#9  0x00000000006fe676 in mysql_inplace_alter_table (thd=0x7fa376b57070, table_list=0x7fa36e5a4198, table=0x7fa36e49e470, altered_table=0x7fa36e611070, ha_alter_info=0x7fa384593260, inplace_supported=HA_ALTER_INPLACE_NO_LOCK_AFTER_PREPARE, target_mdl_request=0x7fa384592cb0, alter_ctx=0x7fa384593840) at /data/src/10.0/sql/sql_table.cc:7164
 
#10 0x0000000000702cac in mysql_alter_table (thd=0x7fa376b57070, new_db=0x7fa36e5a4158 "test", new_name=0x0, create_info=0x7fa3845944e0, table_list=0x7fa36e5a4198, alter_info=0x7fa384594450, order_num=0, order=0x0, ignore=false) at /data/src/10.0/sql/sql_table.cc:8970
 
#11 0x000000000076b8c9 in Sql_cmd_alter_table::execute (this=0x7fa36e5a4858, thd=0x7fa376b57070) at /data/src/10.0/sql/sql_alter.cc:312
 
#12 0x00000000006515f4 in mysql_execute_command (thd=0x7fa376b57070) at /data/src/10.0/sql/sql_parse.cc:5115
 
#13 0x0000000000654c4a in mysql_parse (thd=0x7fa376b57070, rawbuf=0x7fa36e5a4088 "alter table test.t1 add column b int first", length=42, parser_state=0x7fa384595640) at /data/src/10.0/sql/sql_parse.cc:6634
 
#14 0x000000000064756a in dispatch_command (command=COM_QUERY, thd=0x7fa376b57070, packet=0x7fa37c5dc071 "alter table test.t1 add column b int first", packet_length=42) at /data/src/10.0/sql/sql_parse.cc:1297
 
#15 0x000000000064686a in do_command (thd=0x7fa376b57070) at /data/src/10.0/sql/sql_parse.cc:1000
 
#16 0x000000000076701c in do_handle_one_connection (thd_arg=0x7fa376b57070) at /data/src/10.0/sql/sql_connect.cc:1377
 
#17 0x0000000000766d8e in handle_one_connection (arg=0x7fa376b57070) at /data/src/10.0/sql/sql_connect.cc:1292
 
#18 0x0000000000a0263c in pfs_spawn_thread (arg=0x7fa376b07670) at /data/src/10.0/storage/perfschema/pfs.cc:1861
 
#19 0x00007fa3841dc064 in start_thread (arg=0x7fa384596700) at pthread_create.c:309
 
#20 0x00007fa38260262d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Comment by Marko Mäkelä [ 2018-06-05 ]

By the design of ALTER TABLE…ALGORITHM=INPLACE, the post-commit adjustments to the InnoDB dictionary cache must succeed. Anything that can fail should be caught before the operation is committed inside InnoDB.

I would primarily try to find out why any of these conditions hold for such a long time:

	if (node->n_pending > 0
 
	    || node->n_pending_flushes > 0
 
	    || node->being_extended) {
 
		/* There are pending i/o's or flushes or the file is
 
		currently being extended, sleep for a while and
 
		retry */
 
		sleep = true;
 
	} else if (node->modification_counter > node->flush_counter) {
 
		/* Flush the space */
 
		sleep = flush = true;

wlad, do we actually need this code? Is there really any problem to rename a file on Windows while the same process is accessing it via open handles? If this retry logic can be removed, then I think that also the fault injection that elenst exercised can be removed.

Comment by Shaohua Wang [ 2022-08-10 ]

Marko, I was able to find out the root cause finally.

please refer to: https://bugs.mysql.com/bug.php?id=108087

there is a workaroud: turn off chagne buffer.

the fix is simple: 

--- a/storage/innobase/fil/fil0fil.cc
 
+++ b/storage/innobase/fil/fil0fil.cc
 
@@ -3458,10 +3458,14 @@ func_exit:
 
                retry */
 
                sleep = true;
 
 
 
+               space->stop_ios = false;
 
+
 
        } else if (node->modification_counter > node->flush_counter) {
 
                /* Flush the space */
 
                sleep = flush = true;
 
 
 
+               space->stop_ios = false;
 
+
 
        } else if (node->is_open) {
 
                /* Close the file */

Comment by Marko Mäkelä [ 2022-08-10 ]

tiandiwonder, thank you. The I/O layer in MariaDB’s InnoDB storage engine is simpler compared to MySQL, thanks to wlad. Your patch to fil_rename_tablespace() could fix the problem in MySQL. Our fix removed the retry loop from that function altogether and relaxed the file locking on Microsoft Windows so that InnoDB data files may be renamed while they are open for writing. That is, there is no need to fsync() and close() the file before renaming.

Another anomaly due to unoptimal use of Microsoft Windows APIs was that synchronous and asynchronous I/O calls could not be used on the same file. So, InnoDB first opened files in synchronous mode, then closed and reopened for asynchronous I/O. wlad simplified this in MariaDB 5.5 already.

Generated at Thu Feb 08 08:26:33 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.