Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2.2, 10.3.0
-
None
Description
to reproduce: ./mtr innodb.innodb-index innodb.log_file_name -no-reorder
CURRENT_TEST: innodb.log_file_name
|
mysqltest: At line 135: query 'SELECT * FROM t3' failed: 2013: Lost connection to MySQL server during query
|
|
|
The result from queries just before the failure was:
|
< snip >
|
.*InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.*/ in mysqld.1.err
|
# Fault 5: Wrong type of data file
|
SELECT * FROM INFORMATION_SCHEMA.ENGINES
|
WHERE engine = 'innodb'
|
AND support IN ('YES', 'DEFAULT', 'ENABLED');
|
ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS
|
InnoDB YES Supports transactions, row-level locking, foreign keys and encryption for tables YES YES YES
|
SELECT * FROM INFORMATION_SCHEMA.ENGINES
|
WHERE engine = 'innodb'
|
AND support IN ('YES', 'DEFAULT', 'ENABLED');
|
ENGINE SUPPORT COMMENT TRANSACTIONS XA SAVEPOINTS
|
InnoDB YES Supports transactions, row-level locking, foreign keys and encryption for tables YES YES YES
|
NOT FOUND /\[ERROR\] InnoDB: Cannot read first page of .*t2.ibd.*/ in mysqld.1.err
|
NOT FOUND /\[ERROR\] InnoDB: Datafile .*t2.*\. Cannot determine the space ID from the first 64 pages.*/ in mysqld.1.err
|
SELECT * FROM t2;
|
a
|
9
|
101
|
347
|
SELECT * FROM t3;
|
|
|
|
2018-02-15 13:52:35 140482482726656 [ERROR] InnoDB: Flag mismatch in page [page id: space=403, page number=3] index `PRIMARY` of table `test`.`t3`
|
2018-02-15 13:52:35 0x7fc4a07ae700 InnoDB: Assertion failure in file /home/alice/git/10.2/storage/innobase/btr/btr0btr.cc line 248
|
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.
|
180215 13:52:35 [ERROR] mysqld got signal 6 ;
|
|
|
Server version: 10.2.14-MariaDB-debug-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=1
|
max_threads=153
|
thread_count=7
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63125 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7fc460000b00
|
Attempting backtrace. You can use the following information to find out
|
where mysqld died. If you see no messages after this, something went
|
terribly wrong...
|
stack_bottom = 0x7fc4a07ade70 thread_stack 0x49000
|
mysys/stacktrace.c:267(my_print_stacktrace)[0x55f1be4bb584]
|
sql/signal_handler.cc:168(handle_fatal_signal)[0x55f1bdd4debb]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fc4affc6390]
|
linux/raise.c:54(__GI_raise)[0x7fc4af37f428]
|
stdlib/abort.c:91(__GI_abort)[0x7fc4af38102a]
|
ut/ut0dbg.cc:62(__static_initialization_and_destruction_0(int, int))[0x55f1be1b74dc]
|
btr/btr0btr.cc:251(btr_root_block_get(dict_index_t const*, unsigned long, mtr_t*))[0x55f1be1c1d75]
|
btr/btr0btr.cc:277(btr_root_get(dict_index_t const*, mtr_t*))[0x55f1be1c1e52]
|
btr/btr0btr.cc:626(btr_get_size(dict_index_t*, unsigned long, mtr_t*))[0x55f1be1c280d]
|
dict/dict0stats.cc:870(dict_stats_update_transient_for_index(dict_index_t*))[0x55f1be28a254]
|
dict/dict0stats.cc:959(dict_stats_update_transient(dict_table_t*))[0x55f1be28a541]
|
dict/dict0stats.cc:3364(dict_stats_update(dict_table_t*, dict_stats_upd_option_t))[0x55f1be28fa09]
|
include/dict0stats.ic:166(dict_stats_init(dict_table_t*))[0x55f1bdf94a91]
|
handler/ha_innodb.cc:6461(ha_innobase::open(char const*, int, unsigned int))[0x55f1bdf9ed46]
|
sql/handler.cc:2501(handler::ha_open(TABLE*, char const*, int, unsigned int))[0x55f1bdd54588]
|
sql/table.cc:3328(open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool))[0x55f1bdbe0600]
|
sql/sql_base.cc:1877(open_table(THD*, TABLE_LIST*, Open_table_context*))[0x55f1bda6b63a]
|
sql/sql_base.cc:3409(open_and_process_table(THD*, LEX*, TABLE_LIST*, unsigned int*, unsigned int, Prelocking_strategy*, bool, Open_table_context*))[0x55f1bda6e0ec]
|
sql/sql_base.cc:3928(open_tables(THD*, DDL_options_st const&, TABLE_LIST**, unsigned int*, unsigned int, Prelocking_strategy*))[0x55f1bda6f287]
|
sql/sql_base.cc:4682(open_and_lock_tables(THD*, DDL_options_st const&, TABLE_LIST*, bool, unsigned int, Prelocking_strategy*))[0x55f1bda70a3c]
|
sql/sql_base.h:494(open_and_lock_tables(THD*, TABLE_LIST*, bool, unsigned int))[0x55f1bda63ed6]
|
sql/sql_parse.cc:6377(execute_sqlcom_select(THD*, TABLE_LIST*))[0x55f1bdae7bf0]
|
sql/sql_parse.cc:3467(mysql_execute_command(THD*))[0x55f1bdadde16]
|
sql/sql_parse.cc:7902(mysql_parse(THD*, char*, unsigned int, Parser_state*, bool, bool))[0x55f1bdaeba82]
|
sql/sql_parse.cc:1808(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x55f1bdad96b3]
|
sql/sql_parse.cc:1360(do_command(THD*))[0x55f1bdad800f]
|
sql/sql_connect.cc:1335(do_handle_one_connection(CONNECT*))[0x55f1bdc2636f]
|
sql/sql_connect.cc:1242(handle_one_connection)[0x55f1bdc260ef]
|
perfschema/pfs.cc:1864(pfs_spawn_thread)[0x55f1bdf83938]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fc4affbc6ba]
|
x86_64/clone.S:111(clone)[0x7fc4af45141d]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fc460012598): SELECT * FROM t3
|
Connection ID (thread ID): 8
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
|
|
Thread 1 (Thread 0x7fc4a07ae700 (LWP 10068)):
|
#0 __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
|
#1 0x000055f1be4bb676 in my_write_core (sig=6) at /home/alice/git/10.2/mysys/stacktrace.c:477
|
#2 0x000055f1bdd4e2e3 in handle_fatal_signal (sig=6) at /home/alice/git/10.2/sql/signal_handler.cc:305
|
#3 <signal handler called>
|
#4 0x00007fc4af37f428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
|
#5 0x00007fc4af38102a in __GI_abort () at abort.c:89
|
#6 0x000055f1be1b74dc in ut_dbg_assertion_failed (expr=0x0, file=0x55f1be762fa8 "/home/alice/git/10.2/storage/innobase/btr/btr0btr.cc", line=248) at /home/alice/git/10.2/storage/innobase/ut/ut0dbg.cc:61
|
#7 0x000055f1be1c1d75 in btr_root_block_get (index=0x7fc460023eb8, mode=4, mtr=0x7fc4a07aac80) at /home/alice/git/10.2/storage/innobase/btr/btr0btr.cc:248
|
#8 0x000055f1be1c1e52 in btr_root_get (index=0x7fc460023eb8, mtr=0x7fc4a07aac80) at /home/alice/git/10.2/storage/innobase/btr/btr0btr.cc:277
|
#9 0x000055f1be1c280d in btr_get_size (index=0x7fc460023eb8, flag=2, mtr=0x7fc4a07aac80) at /home/alice/git/10.2/storage/innobase/btr/btr0btr.cc:626
|
#10 0x000055f1be28a254 in dict_stats_update_transient_for_index (index=0x7fc460023eb8) at /home/alice/git/10.2/storage/innobase/dict/dict0stats.cc:870
|
#11 0x000055f1be28a541 in dict_stats_update_transient (table=0x7fc46013d448) at /home/alice/git/10.2/storage/innobase/dict/dict0stats.cc:957
|
#12 0x000055f1be28fa09 in dict_stats_update (table=0x7fc46013d448, stats_upd_option=DICT_STATS_RECALC_TRANSIENT) at /home/alice/git/10.2/storage/innobase/dict/dict0stats.cc:3362
|
#13 0x000055f1bdf94a91 in dict_stats_init (table=0x7fc46013d448) at /home/alice/git/10.2/storage/innobase/include/dict0stats.ic:166
|
#14 0x000055f1bdf9ed46 in ha_innobase::open (this=0x7fc46013c278, name=0x7fc460136e80 "./test/t3") at /home/alice/git/10.2/storage/innobase/handler/ha_innodb.cc:6461
|
#15 0x000055f1bdd54588 in handler::ha_open (this=0x7fc46013c278, table_arg=0x7fc46013b670, name=0x7fc460136e80 "./test/t3", mode=2, test_if_locked=18) at /home/alice/git/10.2/sql/handler.cc:2501
|
#16 0x000055f1bdbe0600 in open_table_from_share (thd=0x7fc460000b00, share=0x7fc460136978, alias=0x7fc460012768 "t3", db_stat=33, prgflag=8, ha_open_flags=18, outparam=0x7fc46013b670, is_create_table=false) at /home/alice/git/10.2/sql/table.cc:3328
|
#17 0x000055f1bda6b63a in open_table (thd=0x7fc460000b00, table_list=0x7fc460012770, ot_ctx=0x7fc4a07ac010) at /home/alice/git/10.2/sql/sql_base.cc:1877
|
#18 0x000055f1bda6e0ec in open_and_process_table (thd=0x7fc460000b00, lex=0x7fc4600045e0, tables=0x7fc460012770, counter=0x7fc4a07ac0a4, flags=0, prelocking_strategy=0x7fc4a07ac120, has_prelocking_list=false, ot_ctx=0x7fc4a07ac010) at /home/alice/git/10.2/sql/sql_base.cc:3409
|
#19 0x000055f1bda6f287 in open_tables (thd=0x7fc460000b00, options=..., start=0x7fc4a07ac088, counter=0x7fc4a07ac0a4, flags=0, prelocking_strategy=0x7fc4a07ac120) at /home/alice/git/10.2/sql/sql_base.cc:3928
|
#20 0x000055f1bda70a3c in open_and_lock_tables (thd=0x7fc460000b00, options=..., tables=0x7fc460012770, derived=true, flags=0, prelocking_strategy=0x7fc4a07ac120) at /home/alice/git/10.2/sql/sql_base.cc:4682
|
#21 0x000055f1bda63ed6 in open_and_lock_tables (thd=0x7fc460000b00, tables=0x7fc460012770, derived=true, flags=0) at /home/alice/git/10.2/sql/sql_base.h:494
|
#22 0x000055f1bdae7bf0 in execute_sqlcom_select (thd=0x7fc460000b00, all_tables=0x7fc460012770) at /home/alice/git/10.2/sql/sql_parse.cc:6377
|
#23 0x000055f1bdadde16 in mysql_execute_command (thd=0x7fc460000b00) at /home/alice/git/10.2/sql/sql_parse.cc:3467
|
#24 0x000055f1bdaeba82 in mysql_parse (thd=0x7fc460000b00, rawbuf=0x7fc460012598 "SELECT * FROM t3", length=16, parser_state=0x7fc4a07ad200, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:7902
|
#25 0x000055f1bdad96b3 in dispatch_command (command=COM_QUERY, thd=0x7fc460000b00, packet=0x7fc460008951 "SELECT * FROM t3", packet_length=16, is_com_multi=false, is_next_command=false) at /home/alice/git/10.2/sql/sql_parse.cc:1806
|
#26 0x000055f1bdad800f in do_command (thd=0x7fc460000b00) at /home/alice/git/10.2/sql/sql_parse.cc:1360
|
#27 0x000055f1bdc2636f in do_handle_one_connection (connect=0x55f1c0857320) at /home/alice/git/10.2/sql/sql_connect.cc:1335
|
#28 0x000055f1bdc260ef in handle_one_connection (arg=0x55f1c0857320) at /home/alice/git/10.2/sql/sql_connect.cc:1241
|
#29 0x000055f1bdf83938 in pfs_spawn_thread (arg=0x55f1c083a0a0) at /home/alice/git/10.2/storage/perfschema/pfs.cc:1862
|
#30 0x00007fc4affbc6ba in start_thread (arg=0x7fc4a07ae700) at pthread_create.c:333
|
#31 0x00007fc4af45141d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
|
Attachments
Issue Links
- causes
-
-
- Closed
-
- duplicates
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
Activity
I have analyzed and reported exactly this same case in MDEV-12905.
The new (and very useful) piece of information is the deterministic invocation:
./mtr --mem innodb.innodb-index innodb.log_file_name -no-reorder
|
./mtr innodb.innodb-index innodb.log_file_name --no-reorder
|
gives the above assert.
First of all, innodb.innodb-index doesn't do restart. when server process innodb.log_file_name, there is a large set of redo logs
to recover. (start from innodb-index test redo logs.)
During recovery, redo logs are added to the hash table. Due to large set of redo logs, hash table memory exceeds the available memory.
Once hash table ran out of memory then InnoDB doesn't store any redo log into hash table. InnoDB just process MLOG_FILE* records.
let's move on to the particular scenario:
CREATE TABLE t1(a INT PRIMARY KEY) ENGINE=InnoDB;
|
|
|
--source include/no_checkpoint_start.inc
|
CREATE TABLE t3(a INT PRIMARY KEY) ENGINE=InnoDB;
|
|
|
BEGIN;
|
INSERT INTO t3 VALUES (33101),(347);
|
INSERT INTO t1 VALUES (42),(9),(101);
|
RENAME TABLE t1 TO t2;
|
UPDATE t2 SET a=347 where a=42;
|
COMMIT;
|
|
|
--let CLEANUP_IF_CHECKPOINT=DROP TABLE t2,t3;
|
--source include/no_checkpoint_end.inc
|
....
|
.....
|
--echo # Fault 2: Wrong space_id in a dirty file, and a missing file.
|
--move_file $MYSQLD_DATADIR/test/t3.ibd $MYSQLD_DATADIR/test/t1.ibd
|
|
|
--source include/start_mysqld.inc
|
Here the missing file is t3.ibd. Expectation is that InnoDB engine initialization should fail. But what really happened is that InnoDB
engine loads successfully and normal shutdown happens.(checkpoint happens as a part of normal shutdown). Later in the test case,
we restore t3 and do select query on it and it leads to crash (zero filled page.)
Reason for successful engine initialization:
InnoDB has variable(recv_spaces) to store the list of MLOG_FILE_NAME records. It stores space_id, fname(space_name, fil_space_t*, deleted flag).
Deleted flag will be set if it detects MLOG_FILE_DELETE redo record. recv_spaces contains the following missing tablespace:
space 226 name ./test/t2.ibd, deleted 0
space 227 name ./test/t3.ibd, deleted 0
In recv_init_crash_recovery_spaces(), InnoDB validates all the tablespace were found during crash recovery. Basically it iterates all space id stored in hash table and
check whether the redo logs belongs to missing space id is present. If yes then InnoDB displays the error message and InnoDB fails during initialization.
In our case, hash table ran out of memory before processing redo logs belongs to missing tablespace. So there is no point in checking hash table for missing
tablespace validation. InnoDB starts successfully and it does normal shutdown. Redo log belongs to t2,t3 doesn't apply during the recovery because of tablespace missing.
Log:
===
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 51.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 52.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 51.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 52.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 51.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 51.
|
...........
|
............
|
..............
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 146.
|
|
|
Hash table ran out of memory.
|
|
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 147.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 147.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 147.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 227, since the redo log references ./test/t1.ibd with space ID 147.
|
.........
|
|
|
2018-03-21 23:06:23 0 [Note] InnoDB: Ignoring data file './test/t1.ibd' with space ID 226. Another data file called ./test/t2.ibd exists with the same space ID.
|
2018-03-21 23:06:23 0 [Note] InnoDB: Tablespace 227 was not found at './test/t3.ibd', but there were no modifications either.
|
t3.ibd modifications logs were not present in hash table. (but it exists in redo log). Problem is with the tablespace validation during recovery.
thiru, can you please debug this? I can repeat it.