Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-25683

Atomic DDL: With innodb_force_recovery=3 InnoDB: Trying to load index but the index tree has been freed

    XMLWordPrintable

Details

    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

          Activity

            People

              marko Marko Mäkelä
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.