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

atomic.rename_table test case fails on bb-10.6-MDEV-27022 branch

Details

    Description

      InnoDB fails to identify the tablespace after recovery in rename_table test case.

      2021-11-23 18:35:55 0 [ERROR] InnoDB: Tablespace 6 was not found at ./test/t2.ibd.
      		 
      2021-11-23 18:35:55 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
      		 
      2021-11-23 18:35:55 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1447] with error Tablespace not found

      InnoDB removes the space id from deferred tablespace when name is being matched. I think defer tablespace should handle rename table in a better way

      Attachments

        Issue Links

          blocks

          Bug - A problem which impairs or prevents the functions of the product. MDEV-27022 Buffer pool is being flushed during recovery

          • Major - Major loss of function.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-28923 atomic.rename_table occasionally fails

          • Major - Major loss of function.
          • Closed
          duplicates

          Bug - A problem which impairs or prevents the functions of the product. MDEV-26954 Failed ALTER causes table corruption after recovery - Tablespace not found

          • Major - Major loss of function.
          • Closed
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-27234 InnoDB dictionary recovery wrongly uses READ UNCOMMITTED isolation level instead of READ COMMITTED

          • Major - Major loss of function.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            thiru Thirunarayanan Balathandayuthapani added a comment -

            Patch is in bb-10.6-MDEV-27111

            thiru Thirunarayanan Balathandayuthapani added a comment - Patch is in bb-10.6- MDEV-27111
            thiru Thirunarayanan Balathandayuthapani added a comment -

            matthias reported the following issue:

            pluto:/data/rqg/results/1637683377/TBR-1105/data/rqg/1637683377/102/1/rr
            		 
            _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1     # Fate of DB server till SIGKILL
            		 
            _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-2     # Restart attempt which fails with
            		 
             
            		 
            [rr 590711 6386]2021-11-23 19:16:54 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=50236030,53957790
            		 
            [rr 590711 6503]2021-11-23 19:16:54 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-6442a-12.ibd' with space ID 63. Another data file called ./test/t4.ibd exists with the same space ID.
            		 
            [rr 590711 6581]2021-11-23 19:16:54 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-6442a-19.ibd' with space ID 65. Another data file called ./test/t2.ibd exists with the same space ID.
            		 
            [rr 590711 6919]2021-11-23 19:16:55 0 [ERROR] InnoDB: Tablespace 72 was not found at ./test/t5.ibd.
            		 
            [rr 590711 6923]2021-11-23 19:16:55 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.
            		 
            [rr 590711 6927]2021-11-23 19:16:55 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1447] with error Tablespace not found
            		 
            [rr 590711 6931]2021-11-23 19:16:55 0 [Note] InnoDB: Starting shutdown...

            thiru Thirunarayanan Balathandayuthapani added a comment - matthias reported the following issue: pluto:/data/rqg/results/1637683377/TBR-1105/data/rqg/1637683377/102/1/rr _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1 # Fate of DB server till SIGKILL _RR_TRACE_DIR="." rr replay --mark-stdio mysqld-2 # Restart attempt which fails with   [rr 590711 6386]2021-11-23 19:16:54 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=50236030,53957790 [rr 590711 6503]2021-11-23 19:16:54 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-6442a-12.ibd' with space ID 63. Another data file called ./test/t4.ibd exists with the same space ID. [rr 590711 6581]2021-11-23 19:16:54 0 [Note] InnoDB: Ignoring data file './test/#sql-alter-6442a-19.ibd' with space ID 65. Another data file called ./test/t2.ibd exists with the same space ID. [rr 590711 6919]2021-11-23 19:16:55 0 [ERROR] InnoDB: Tablespace 72 was not found at ./test/t5.ibd. [rr 590711 6923]2021-11-23 19:16:55 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace. [rr 590711 6927]2021-11-23 19:16:55 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1447] with error Tablespace not found [rr 590711 6931]2021-11-23 19:16:55 0 [Note] InnoDB: Starting shutdown...
            thiru Thirunarayanan Balathandayuthapani added a comment -

            I think there could be race condition between rename operation and fil_names_clear() written during checkpoint operation
            we do write redo log for rename operation before renaming the tablespace (space->chain->start)->name

             
            		 
            fil_name_write_rename(id, old_path, path);
            		 
              }
            		 
             
            		 
              return fil_rename_tablespace(id, old_path, path) ? DB_SUCCESS : DB_ERROR;

            If we do checkpoint(fil_names_clear) between these 2 operation then InnoDB will try to recover the table using old_name
            some like this:

            lsn: 1000
            		 
            mlog_file_rename 5, t1, #sql-ib183
            		 
             
            		 
            lsn:1100
            		 
            mlog_file_name 5, t1
            		 
             
            		 
            LOG_CHECKPOINT_END_LSN is 1100

            thiru Thirunarayanan Balathandayuthapani added a comment - I think there could be race condition between rename operation and fil_names_clear() written during checkpoint operation we do write redo log for rename operation before renaming the tablespace (space->chain->start)->name   fil_name_write_rename(id, old_path, path); }   return fil_rename_tablespace(id, old_path, path) ? DB_SUCCESS : DB_ERROR; If we do checkpoint(fil_names_clear) between these 2 operation then InnoDB will try to recover the table using old_name some like this: lsn: 1000 mlog_file_rename 5, t1, #sql-ib183   lsn:1100 mlog_file_name 5, t1   LOG_CHECKPOINT_END_LSN is 1100
            marko Marko Mäkelä added a comment -

            MDEV-27234 is another bug in the recovery of rename operations.

            marko Marko Mäkelä added a comment - MDEV-27234 is another bug in the recovery of rename operations.
            marko Marko Mäkelä added a comment -

            For the record, before the fix of MDEV-28870 I was able to reproduce the following failure locally:

            10.6 0e4cf497ca11a7298e2bd896cb594bd52085a1d4

            		 
            atomic.rename_table 'innodb'             w3 [ fail ]
            		 
                    Test ended at 2022-06-20 11:21:37
            		 
             
            		 
            CURRENT_TEST: atomic.rename_table
            		 
            mysqltest: At line 155: query 'let $res=`select t1.a+t2.b+t3.c+t4.d from t1,t2,t3,t4`' failed: ER_UNKNOWN_STORAGE_ENGINE (1286): Unknown storage engine 'InnoDB'
            		 
            …
            		 
            2022-06-20 11:21:36 0 [ERROR] InnoDB: Tablespace 8 was not found at ./test/t5.ibd.
            		 
            2022-06-20 11:21:36 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1197] with error Tablespace not found
            		 
            2022-06-20 11:21:36 0 [ERROR] Plugin 'InnoDB' init function returned error.
            		 
            2022-06-20 11:21:36 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.

            With the fix of MDEV-28870, the test passed for 120×10 runs (on a system where nproc reports 40).
            My test invocation was the following, on a debug build:

            nice ./mtr --mysqld=--innodb-max-dirty-pages-pct=0 --repeat=10 --parallel=120 atomic.rename_table{,,,,,,,,,,,,,,,,,,,}{,,,,,}

            I think that innodb_max_dirty_pages_pct=0 should increase the chances of hitting the MDEV-28870 scenario, that is, a race condition between log checkpoint and processing FILE_RENAME or FILE_DELETE.

            marko Marko Mäkelä added a comment - For the record, before the fix of MDEV-28870 I was able to reproduce the following failure locally: 10.6 0e4cf497ca11a7298e2bd896cb594bd52085a1d4 atomic.rename_table 'innodb' w3 [ fail ] Test ended at 2022-06-20 11:21:37   CURRENT_TEST: atomic.rename_table mysqltest: At line 155: query 'let $res=`select t1.a+t2.b+t3.c+t4.d from t1,t2,t3,t4`' failed: ER_UNKNOWN_STORAGE_ENGINE (1286): Unknown storage engine 'InnoDB' … 2022-06-20 11:21:36 0 [ERROR] InnoDB: Tablespace 8 was not found at ./test/t5.ibd. 2022-06-20 11:21:36 0 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[1197] with error Tablespace not found 2022-06-20 11:21:36 0 [ERROR] Plugin 'InnoDB' init function returned error. 2022-06-20 11:21:36 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. With the fix of MDEV-28870 , the test passed for 120×10 runs (on a system where nproc reports 40). My test invocation was the following, on a debug build: nice . /mtr --mysqld=--innodb-max-dirty-pages-pct=0 --repeat=10 --parallel=120 atomic.rename_table{,,,,,,,,,,,,,,,,,,,}{,,,,,} I think that innodb_max_dirty_pages_pct=0 should increase the chances of hitting the MDEV-28870 scenario, that is, a race condition between log checkpoint and processing FILE_RENAME or FILE_DELETE .

            People

              marko Marko Mäkelä
              thiru Thirunarayanan Balathandayuthapani
              Votes:
              0 Vote for this issue
              Watchers:
              3 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.