Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.14, 10.0(EOL), 10.1(EOL), 10.2(EOL), 10.3(EOL)
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
|
Attachments
Issue Links
- relates to
-
-
- Closed
-
Activity
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
|
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.
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 */ |
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.
The server crash occurs several minutes later:
InnoDB: Pending reads 0, writes 02018-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 7890InnoDB: Failing assertion: error == DB_SUCCESSInnoDB: 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, evenInnoDB: immediately after the mysqld startup, there may beInnoDB: corruption in the InnoDB tablespace. Please refer toInnoDB: https://mariadb.com/kb/en/library/xtradbinnodb-recovery-modes/InnoDB: about forcing recovery.Crash log attached.