Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.6.1, 10.6.2
Description
The test was running ALTER TABLE in two threads when it was sigkill-ed. The standard crash recovery seems to work all right (no errors reported and the server starts, other than numerous [Note] records "InnoDB: At LSN: ...: unable to open file ... for tablespace ..."), as well as innodb_force_recovery=[12], but with innodb_force_recovery=3 it throws errors and ends with an assertion failure.
The original test was run on bb-10.6-monty-innodb 60f144ef1f. The recovery failure on a stored datadir is reproducible on bb-10.6-monty be1dcc8aa.
|
bb-10.6-monty be1dcc8aa |
2021-05-15 1:39:51 0 [Note] InnoDB: Opened 2 undo tablespaces
|
2021-05-15 1:39:51 0 [Warning] InnoDB: innodb_undo_tablespaces=0 disables dedicated undo log tablespaces
|
2021-05-15 1:39:51 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=54267,54267
|
2021-05-15 1:39:51 0 [Note] InnoDB: At LSN: 471698: unable to open file ./test/#sql-alter-27122f-f.ibd for tablespace 34
|
2021-05-15 1:39:51 0 [Note] InnoDB: At LSN: 492629: unable to open file ./test/#sql-backup-27122f-f.ibd for tablespace 15
|
2021-05-15 1:39:51 0 [Note] InnoDB: At LSN: 552122: unable to open file ./test/#sql-backup-27122f-10.ibd for tablespace 11
|
...
|
2021-05-15 1:39:52 0 [Note] InnoDB: Opened 2 undo tablespaces
|
2021-05-15 1:39:52 0 [Warning] InnoDB: innodb_undo_tablespaces=0 disables dedicated undo log tablespaces
|
2021-05-15 1:39:52 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 19 row operations to undo
|
2021-05-15 1:39:52 0 [Note] InnoDB: Trx id counter is 2959
|
2021-05-15 1:39:52 0 [Note] InnoDB: Starting final batch to recover 180 pages from redo log.
|
2021-05-15 1:39:58 0 [Note] InnoDB: 128 rollback segments in 2 undo tablespaces are active.
|
2021-05-15 1:39:58 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
|
2021-05-15 1:39:58 0 [Note] InnoDB: Creating shared tablespace for temporary tables
|
2021-05-15 1:39:58 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
|
2021-05-15 1:39:58 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
|
2021-05-15 1:39:58 0 [Note] InnoDB: 10.6.1 started; log sequence number 4332081; transaction id 2959
|
2021-05-15 1:39:58 0 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!
|
2021-05-15 1:39:58 0 [Note] InnoDB: Loading buffer pool(s) from /mnt-hd8t/src/bb-10.6-monty/data/ib_buffer_pool
|
2021-05-15 1:39:58 0 [Note] Plugin 'FEEDBACK' is disabled.
|
2021-05-15 1:39:58 0 [Note] InnoDB: Buffer pool(s) load completed at 210515 1:39:58
|
2021-05-15 1:39:58 0 [ERROR] InnoDB: Trying to load index `PRIMARY` for table `test`.`#sql-alter-27122f-10`, but the index tree has been freed!
|
2021-05-15 1:39:58 0 [Note] InnoDB: Index is corrupt but forcing load into data dictionary
|
2021-05-15 1:39:58 0 [ERROR] InnoDB: A record lock wait happens in a dictionary operation. index `CLUST_IND` of table `SYS_TABLES`. Submit a detailed bug report to https://jira.mariadb.org/
|
mysqld: /data/src/bb-10.6-monty/storage/innobase/lock/lock0lock.cc:1262: dberr_t lock_rec_enqueue_waiting(ib_lock_t*, unsigned int, page_id_t, const ib_page_t*, ulint, dict_index_t*, que_thr_t*, lock_prdt_t*): Assertion `0' failed.
|
210515 1:39:58 [ERROR] mysqld got signal 6 ;
|
 |
#7 0x00007fbcfbf8df36 in __GI___assert_fail (assertion=0x555581499806 "0", file=0x55558149b3d0 "/data/src/bb-10.6-monty/storage/innobase/lock/lock0lock.cc", line=1262, function=0x55558149c3b0 "dberr_t lock_rec_enqueue_waiting(ib_lock_t*, unsigned int, page_id_t, const ib_page_t*, ulint, dict_index_t*, que_thr_t*, lock_prdt_t*)") at assert.c:101
|
#8 0x000055558081aa66 in lock_rec_enqueue_waiting (c_lock=0x7fbcf90cd1f0, type_mode=3, id=..., page=0x7fbcd8d60000 "", heap_no=39, index=0x5555845794c8, thr=0x555584787938, prdt=0x0) at /data/src/bb-10.6-monty/storage/innobase/lock/lock0lock.cc:1262
|
#9 0x000055558081cb34 in lock_rec_lock (impl=false, mode=3, block=0x7fbcd8029f88, heap_no=39, index=0x5555845794c8, thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/lock/lock0lock.cc:1508
|
#10 0x000055558083d9b4 in lock_clust_rec_read_check_and_lock (flags=0, block=0x7fbcd8029f88, rec=0x7fbcd8d60bc5 "test/#sql-alter-27122f-10", index=0x5555845794c8, offsets=0x7ffd185c0cd0, mode=LOCK_X, gap_mode=0, thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/lock/lock0lock.cc:5261
|
#11 0x0000555580aacf29 in sel_set_rec_lock (pcur=0x555584786af0, rec=0x7fbcd8d60bc5 "test/#sql-alter-27122f-10", index=0x5555845794c8, offsets=0x7ffd185c0cd0, mode=3, type=0, thr=0x555584787938, mtr=0x7ffd185c0f30) at /data/src/bb-10.6-monty/storage/innobase/row/row0sel.cc:1282
|
#12 0x0000555580ab006c in row_sel (node=0x5555847866e0, thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/row/row0sel.cc:1829
|
#13 0x0000555580ab263c in row_sel_step (thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/row/row0sel.cc:2342
|
#14 0x0000555580963154 in que_thr_step (thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/que/que0que.cc:629
|
#15 0x00005555809639cf in que_run_threads_low (thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/que/que0que.cc:709
|
#16 0x0000555580963bd2 in que_run_threads (thr=0x555584787938) at /data/src/bb-10.6-monty/storage/innobase/que/que0que.cc:729
|
#17 0x0000555580964078 in que_eval_sql (info=0x5555845f8908, sql=0x5555814f3c00 "PROCEDURE DROP_VIRTUAL_PROC () IS\ntid CHAR;\nBEGIN\nSELECT ID INTO tid FROM SYS_TABLES\nWHERE NAME = :name FOR UPDATE;\nIF (SQL % NOTFOUND) THEN RETURN; END IF;\nDELETE FROM SYS_VIRTUAL WHERE TABLE_ID = ti"..., reserve_dict_mutex=false, trx=0x7fbcf90cf3c0) at /data/src/bb-10.6-monty/storage/innobase/que/que0que.cc:779
|
#18 0x0000555580a3d715 in row_drop_table_for_mysql (name=0x7ffd185c1cd0 "test/#sql-alter-27122f-10", trx=0x7fbcf90cf3c0, sqlcom=SQLCOM_END, create_failed=false, nonatomic=true) at /data/src/bb-10.6-monty/storage/innobase/row/row0mysql.cc:3517
|
#19 0x000055558071e2e7 in ha_innobase::delete_table (this=0x5555842cdea0, name=0x7ffd185c2740 "./test/#sql-alter-27122f-10", sqlcom=SQLCOM_END) at /data/src/bb-10.6-monty/storage/innobase/handler/ha_innodb.cc:13095
|
#20 0x00005555806ee8c1 in ha_innobase::delete_table (this=0x5555842cdea0, name=0x7ffd185c2740 "./test/#sql-alter-27122f-10") at /data/src/bb-10.6-monty/storage/innobase/handler/ha_innodb.cc:13218
|
#21 0x000055557fecf5e5 in hton_drop_table (hton=0x555584245318, path=0x7ffd185c2740 "./test/#sql-alter-27122f-10") at /data/src/bb-10.6-monty/sql/handler.cc:577
|
#22 0x000055557fa6ece9 in ddl_log_execute_action (thd=0x5555842c7288, mem_root=0x7ffd185c29b0, ddl_log_entry=0x7ffd185c29f0) at /data/src/bb-10.6-monty/sql/ddl_log.cc:2023
|
#23 0x000055557fa70f91 in ddl_log_execute_entry_no_lock (thd=0x5555842c7288, first_entry=4) at /data/src/bb-10.6-monty/sql/ddl_log.cc:2373
|
#24 0x000055557fa72efb in ddl_log_execute_recovery () at /data/src/bb-10.6-monty/sql/ddl_log.cc:2733
|
#25 0x000055557f5b15e5 in init_server_components () at /data/src/bb-10.6-monty/sql/mysqld.cc:5325
|
#26 0x000055557f5b2dd2 in mysqld_main (argc=14, argv=0x5555841c2ee8) at /data/src/bb-10.6-monty/sql/mysqld.cc:5652
|
#27 0x000055557f59a91f in main (argc=13, argv=0x7ffd185c4c58) at /data/src/bb-10.6-monty/sql/main.cc:34
|
 |
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x555581d325e0): INTERNAL DDL LOG RECOVER IN PROGRESS
|
 |
Connection ID (thread ID): 0
|
Status: NOT_KILLED
|
Additional remarks:
- should all these [Note] records be there?
- Query (0x555581d325e0): INTERNAL DDL LOG RECOVER IN PROGRESS doesn't look right
Data directory and logs are available. There is no rr profile for the initial run; the profile for recovery can always be created, since the failure is easily reproducible by starting the server on the stored datadir.
Attachments
Issue Links
- is caused by
-
MDEV-17567 Atomic DDL
-
- Closed
-
- relates to
-
-
- Closed
-
-
-
- Closed
-