[MDEV-27111] atomic.rename_table test case fails on bb-10.6-MDEV-27022 branch - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Fixed
Affects Version/s: 10.6
Fix Version/s: 10.6.6, 10.7.2
Component/s: Storage Engine - InnoDB
Labels:
None

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

MDEV-27022 Buffer pool is being flushed during recovery

Closed

MDEV-28923 atomic.rename_table occasionally fails

Closed

duplicates

MDEV-26954 Failed ALTER causes table corruption after recovery - Tablespace not found

Closed

relates to

MDEV-27234 InnoDB dictionary recovery wrongly uses READ UNCOMMITTED isolation level instead of READ COMMITTED

Closed

Activity

Ascending order - Click to sort in descending order

Thirunarayanan Balathandayuthapani created issue - 2021-11-23 13:01

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:07

Field	Original Value	New Value
Description		InnoDB fails to identify the tablespace after recovery in rename_table test case. {code} 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 {code} 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

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:07

Component/s

Storage Engine - InnoDB [ 10129 ]

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:07

Affects Version/s

10.6 [ 24028 ]

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:08

Fix Version/s

10.6 [ 24028 ]

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:08

Status

Open [ 1 ]

Confirmed [ 10101 ]

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 13:08

Assignee

Thirunarayanan Balathandayuthapani [ thiru ]

Thirunarayanan Balathandayuthapani made changes - 2021-11-23 14:30

Assignee	Thirunarayanan Balathandayuthapani [ thiru ]	Marko Mäkelä [ marko ]
Status	Confirmed [ 10101 ]	In Review [ 10002 ]

Thirunarayanan Balathandayuthapani added a comment - 2021-11-23 14:30

Patch is in bb-10.6-MDEV-27111

Thirunarayanan Balathandayuthapani added a comment - 2021-11-23 14:30 Patch is in bb-10.6- MDEV-27111

Thirunarayanan Balathandayuthapani added a comment - 2021-11-26 13:44

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...

Thirunarayanan Balathandayuthapani added a comment - 2021-11-26 13:44 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...

Thirunarayanan Balathandayuthapani added a comment - 2021-11-26 13:46

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

Thirunarayanan Balathandayuthapani added a comment - 2021-11-26 13:46 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

Sergei Golubchik made changes - 2021-12-06 21:36

Workflow

MariaDB v3 [ 127926 ]

MariaDB v4 [ 143807 ]

Thirunarayanan Balathandayuthapani made changes - 2021-12-12 13:39

Fix Version/s		10.6.6 [ 26811 ]
Fix Version/s	10.6 [ 24028 ]
Resolution		Fixed [ 1 ]
Status	In Review [ 10002 ]	Closed [ 6 ]

Thirunarayanan Balathandayuthapani made changes - 2021-12-12 13:40

Fix Version/s

10.7 [ 24805 ]

Thirunarayanan Balathandayuthapani made changes - 2021-12-12 13:40

Fix Version/s		10.7.2 [ 26813 ]
Fix Version/s	10.7 [ 24805 ]

Marko Mäkelä made changes - 2021-12-13 10:32

Link

This issue relates to ~~MDEV-27234~~ [ ~~MDEV-27234~~ ]

Marko Mäkelä added a comment - 2021-12-13 10:32

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

Marko Mäkelä added a comment - 2021-12-13 10:32 MDEV-27234 is another bug in the recovery of rename operations.

Marko Mäkelä made changes - 2021-12-13 10:33

Link

This issue blocks ~~MDEV-27022~~ [ ~~MDEV-27022~~ ]

Thirunarayanan Balathandayuthapani made changes - 2021-12-27 11:23

Link

This issue duplicates ~~MDEV-26954~~ [ ~~MDEV-26954~~ ]

Marko Mäkelä added a comment - 2022-06-20 14:56

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 Mäkelä added a comment - 2022-06-20 14:56 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 Mäkelä made changes - 2022-06-22 09:56

Link

This issue blocks ~~MDEV-28923~~ [ ~~MDEV-28923~~ ]

People

Assignee:: Marko Mäkelä

Reporter:: Thirunarayanan Balathandayuthapani

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2021-11-23 13:01

Updated:: 2022-06-22 09:56

Resolved:: 2021-12-12 13:39

Git Integration

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

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration