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

              Assignee:
              marko Marko Mäkelä
              Reporter:
              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.