[MDEV-30311] system-wide max transaction id corrupted (from MySQL-5.7 upgrade) Created: 2022-12-28  Updated: 2023-11-23  Resolved: 2023-03-03

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.11, 11.0
Fix Version/s: 10.11.3, 11.0.2

Type: Bug Priority: Blocker
Reporter: Daniel Black Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: regression-10.11

Attachments: File 0001-WIP-test-case.patch     File ibdata1.gz     File m57.tar.bz2    
Issue Links:
Blocks
Problem/Incident
is caused by MDEV-19229 Allow innodb_undo_tablespaces to be c... Closed

 Description    

$ docker run -v  m57:/var/lib/mysql:Z -e MYSQL_INITDB_SKIP_TZINFO=1 -e MYSQL_ROOT_PASSWORD=bob --rm  docker.io/library/mysql:5.7
 
2022-12-28 00:12:20+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.40-1.el7 started.
 
...
 
$ podman exec jovial_hertz mysql -u root -pbob -e "set global innodb_fast_shutdown=0;SHUTDOWN"

Use same volume in MariaDB:

11.0.0+1cb0835be98985f20cccd1724ac78de3649eb2e6

 
$ podman run --env   MARIADB_AUTO_UPGRADE=1 -v m57:/var/lib/mysql:Z --user mysql mariadb-31171 bash -x -v docker-entrypoint.sh mariadbd
 
#!/bin/bash
 
set -eo pipefail
 
....
 
+ mariadbd --skip-grant-tables --loose-innodb_buffer_pool_dump_at_shutdown=0 --skip-slave-start --skip-networking --default-time-zone=SYSTEM --socket=/run/mysqld/mysqld.sock --wsrep_on=OFF --expire-logs-days=0 --loose-innodb_buffer_pool_load_at_startup=0
 
++ date --rfc-3339=seconds
 
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:36+00:00' Note 'Waiting for server startup'
 
2022-12-28 00:23:36+00:00 [Note] [Entrypoint]: Waiting for server startup
 
+ extraArgs=()
 
+ '[' -z true ']'
 
+ local i
 
+ for i in {30..0}
 
+ docker_process_sql --database=mysql
 
+ sleep 1
 
2022-12-28  0:23:36 0 [Note] mariadbd (server 11.0.0-MariaDB-1:11.0.0+maria~ubu2204) starting as process 106 ...
 
2022-12-28  0:23:36 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-12-28  0:23:36 0 [Note] InnoDB: Number of transaction pools: 1
 
2022-12-28  0:23:36 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2022-12-28  0:23:36 0 [Note] mariadbd: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2022-12-28  0:23:36 0 [Warning] mariadbd: io_uring_queue_init() failed with ENOSYS: check seccomp filters, and the kernel version (newer than 5.1 required)
 
2022-12-28  0:23:36 0 [Warning] InnoDB: liburing disabled: falling back to innodb_use_native_aio=OFF
 
2022-12-28  0:23:36 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
 
2022-12-28  0:23:36 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-12-28  0:23:36 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
 
2022-12-28  0:23:36 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
 
2022-12-28  0:23:36 0 [Note] InnoDB: Opened 3 undo tablespaces
 
2022-12-28  0:23:36 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
 
2022-12-28  0:23:36 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
 
2022-12-28  0:23:36 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2022-12-28  0:23:36 0 [Note] InnoDB: log sequence number 2774559; transaction id 770
 
2022-12-28  0:23:36 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2022-12-28  0:23:36 0 [ERROR] WSREP: plugin-wsrep-provider can't be enabled if wsrep_on==OFF or wsrep_provider is unset or set to 'none'
 
2022-12-28  0:23:36 0 [ERROR] mariadbd: plugin-wsrep-provider can't be enabled if wsrep_on==OFF or wsrep_provider is unset or set to 'none'
 
2022-12-28  0:23:36 0 [ERROR] Plugin 'wsrep_provider' init function returned error.
 
2022-12-28  0:23:36 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
 
2022-12-28  0:23:36 0 [Note] mariadbd: ready for connections.
 
Version: '11.0.0-MariaDB-1:11.0.0+maria~ubu2204'  socket: '/run/mysqld/mysqld.sock'  port: 0  mariadb.org binary distribution
 
+ for i in {30..0}
 
+ docker_process_sql --database=mysql
 
+ break
 
+ '[' 29 = 0 ']'
 
+ mysql_note 'Temporary server started.'
 
+ mysql_log Note 'Temporary server started.'
 
+ local type=Note
 
+ shift
 
++ date --rfc-3339=seconds
 
2022-12-28 00:23:37+00:00 [Note] [Entrypoint]: Temporary server started.
 
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' Note 'Temporary server started.'
 
+ docker_mariadb_backup_system
 
+ '[' -n '' ']'
 
+ local backup_db=system_mysql_backup_unknown_version.sql.zst
 
+ local oldfullversion=unknown_version
 
+ '[' -r /var/lib/mysql//mysql_upgrade_info ']'
 
+ mysql_note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
 
+ mysql_log Note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
 
+ local type=Note
 
+ shift
 
++ date --rfc-3339=seconds
 
2022-12-28 00:23:37+00:00 [Note] [Entrypoint]: Backing up system database to system_mysql_backup_unknown_version.sql.zst
 
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' Note 'Backing up system database to system_mysql_backup_unknown_version.sql.zst'
 
+ zstd
 
+ mariadb-dump --skip-lock-tables --replace --databases mysql --socket=/run/mysqld/mysqld.sock
 
2022-12-28  0:23:37 4 [Warning] InnoDB: A transaction id in a record of table `mysql`.`engine_cost` is newer than the system-wide maximum.
 
2022-12-28  0:23:37 4 [ERROR] InnoDB: We detected index corruption in an InnoDB type table. You have to dump + drop + reimport the table or, in a case of widespread corruption, dump all InnoDB tables and recreate the whole tablespace. If the mariadbd server crashes after the startup or when you dump the tables. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2022-12-28  0:23:37 4 [ERROR] mariadbd: Index for table 'engine_cost' is corrupt; try to repair it
 
mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0
 
+ mysql_error 'Unable backup system database for upgrade from unknown_version.'
 
+ mysql_log ERROR 'Unable backup system database for upgrade from unknown_version.'
 
+ local type=ERROR
 
+ shift
 
++ date --rfc-3339=seconds
 
+ printf '%s [%s] [Entrypoint]: %s\n' '2022-12-28 00:23:37+00:00' ERROR 'Unable backup system database for upgrade from unknown_version.'
 
2022-12-28 00:23:37+00:00 [ERROR] [Entrypoint]: Unable backup system database for upgrade from unknown_version.
 
+ exit 1

"unknown version" is expected as mysql doesn't generate an automatic mysql_upgrade file.

From amd64-rhel8-dockerlibrary in bb.

 Comments   
Comment by Daniel Black [ 2023-01-04 ]

11.0-1cb0835be98985f20cccd1724ac78de3649eb2e6

 
sql/mariadbd --no-defaults --skip-grant-tables --loose-innodb_buffer_pool_dump_at_shutdown=0 --skip-slave-start --skip-networking --default-time-zone=SYSTEM --socket=/tmp/mysqld.sock --wsrep_on=OFF --expire-logs-days=0 --loose-innodb_buffer_pool_load_at_startup=0 --datadir=/tmp/m57

dump with

 
$ client/mariadb-dump -u root -pbob -S /tmp/mysqld.sock --databases mysql --skip-lock-tables --replace
 
 
 
LOCK TABLES `engine_cost` WRITE;
 
/*!40000 ALTER TABLE `engine_cost` DISABLE KEYS */;
 
mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0

Comment by Daniel Black [ 2023-01-12 ]

Somehow went away by 11.0-944beb9e7acd53488dbfc7edc09bf29e10ce68ab

Comment by Daniel Black [ 2023-02-24 ] 

$ d=build-mariadb-server-11.0-datadir; rm -rf $d; mkdir $d; tar -C $d -xf m57.tar.bz2 
 
 
$ sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose &
 
[1] 239736
 
 
 
~/repos/build-mariadb-server-11.0 
$ 2023-02-24 12:21:41 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239736
 
2023-02-24 12:21:41 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
 
2023-02-24 12:21:41 0 [Note] InnoDB: Number of transaction pools: 1
 
2023-02-24 12:21:41 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2023-02-24 12:21:41 0 [Note] InnoDB: Using liburing
 
2023-02-24 12:21:41 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
 
2023-02-24 12:21:41 0 [Note] InnoDB: Completed initialization of buffer pool
 
2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
 
2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading redo log: 96.000MiB; LSN=2762352
 
2023-02-24 12:21:41 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
 
2023-02-24 12:21:41 0 [Note] InnoDB: Upgrading the change buffer
 
2023-02-24 12:21:41 0 [Note] InnoDB: Upgraded the change buffer: 0 tablespaces, 0 pages
 
2023-02-24 12:21:41 0 [Note] InnoDB: Reinitializing innodb_undo_tablespaces= 3 from 0
 
2023-02-24 12:21:41 0 [Note] InnoDB: Setting O_DIRECT on file .//undo001 failed
 
2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo001 did not exist: new to be created
 
2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo001 size to 10.000MiB
 
2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
 
2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo002 did not exist: new to be created
 
2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo002 size to 10.000MiB
 
2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
 
2023-02-24 12:21:41 0 [Note] InnoDB: Data file .//undo003 did not exist: new to be created
 
2023-02-24 12:21:41 0 [Note] InnoDB: Setting file .//undo003 size to 10.000MiB
 
2023-02-24 12:21:41 0 [Note] InnoDB: Database physically writes the file full: wait...
 
2023-02-24 12:21:41 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
 
2023-02-24 12:21:41 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
 
2023-02-24 12:21:41 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2023-02-24 12:21:41 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794
 
2023-02-24 12:21:41 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2023-02-24 12:21:41 0 [Note] Plugin 'wsrep-provider' is disabled.
 
2023-02-24 12:21:41 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
 
2023-02-24 12:21:41 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:41
 
2023-02-24 12:21:41 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
 
2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93).
 
2023-02-24 12:21:41 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B
 
2023-02-24 12:21:41 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2023-02-24 12:21:41 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
 
2023-02-24 12:21:41 0 [Note] sql/mariadbd: ready for connections.
 
Version: '11.0.2-MariaDB'  socket: '/tmp/build-mariadb-server-11.0.sock'  port: 0  Source distribution
 
killall mariadbd
 
2023-02-24 12:21:46 0 [Note] sql/mariadbd (initiated by: unknown): Normal shutdown
 
2023-02-24 12:21:46 0 [Note] InnoDB: FTS optimize thread exiting.
 
2023-02-24 12:21:46 0 [Note] InnoDB: Starting shutdown...
 
2023-02-24 12:21:46 0 [Note] InnoDB: Dumping buffer pool(s) to /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
 
2023-02-24 12:21:46 0 [Note] InnoDB: Buffer pool(s) dump completed at 230224 12:21:46
 
 
 
# Note the killall mariadbd was on the promt
 
 
 
ql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose & while [ ! -S /tmp/${PWD##*/}.sock ]; do sleep 0.05; done ; client/mariadb-dump --user root -pbob  -S /tmp/${PWD##*/}.sock mysql > /dev/null
 
[2] 239807
 
2023-02-24 12:21:54 0 [Note] Starting MariaDB 11.0.2-MariaDB source revision b4ef9f766db28d258621aa888fdffd168321e3ba as process 239807
 
2023-02-24 12:21:54 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
 
2023-02-24 12:21:54 0 [Note] InnoDB: Number of transaction pools: 1
 
2023-02-24 12:21:54 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
 
2023-02-24 12:21:54 0 [Note] InnoDB: Using liburing
 
2023-02-24 12:21:54 0 [Note] InnoDB: Initializing buffer pool, total size = 128.000MiB, chunk size = 2.000MiB
 
2023-02-24 12:21:54 0 [Note] InnoDB: Completed initialization of buffer pool
 
2023-02-24 12:21:54 0 [Note] InnoDB: Resetting space id's in the doublewrite buffer
 
2023-02-24 12:21:54 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
 
2023-02-24 12:21:54 0 [Note] InnoDB: Opened 3 undo tablespaces
 
2023-02-24 12:21:54 0 [Note] InnoDB: 128 rollback segments in 3 undo tablespaces are active.
 
2023-02-24 12:21:54 0 [Note] InnoDB: Setting O_DIRECT on file ./ibtmp1 failed
 
2023-02-24 12:21:54 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
 
2023-02-24 12:21:54 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770
 
2023-02-24 12:21:54 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2023-02-24 12:21:54 0 [Note] Plugin 'wsrep-provider' is disabled.
 
2023-02-24 12:21:54 0 [Note] InnoDB: Loading buffer pool(s) from /tmp/build-mariadb-server-11.0-datadir/ib_buffer_pool
 
2023-02-24 12:21:54 0 [Note] InnoDB: Buffer pool(s) load completed at 230224 12:21:54
 
2023-02-24 12:21:54 0 [ERROR] Missing system table mysql.roles_mapping; please run mysql_upgrade to create it
 
2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'definer' at position 3 to have type varchar(, found type char(93).
 
2023-02-24 12:21:54 0 [ERROR] Incorrect definition of table mysql.event: expected column 'sql_mode' at position 14 to have type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','IGNORE_BAD_TABLE_OPTIONS','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_BACKSLASH_ESCAPES','STRICT_TRANS_TABLES','STRICT_ALL_TABLES','NO_ZERO_IN_DATE','NO_ZERO_DATE','INVALID_DATES','ERROR_FOR_DIVISION_BY_ZERO','TRADITIONAL','NO_AUTO_CREATE_USER','HIGH_NOT_PRECEDENCE','NO_ENGINE_SUBSTITUTION','PAD_CHAR_TO_FULL_LENGTH','EMPTY_STRING_IS_NULL','SIMULTANEOUS_ASSIGNMENT'), found type set('REAL_AS_FLOAT','PIPES_AS_CONCAT','ANSI_QUOTES','IGNORE_SPACE','NOT_USED','ONLY_FULL_GROUP_BY','NO_UNSIGNED_SUBTRACTION','NO_DIR_IN_CREATE','POSTGRESQL','ORACLE','MSSQL','DB2','MAXDB','NO_KEY_OPTIONS','NO_TABLE_OPTIONS','NO_FIELD_OPTIONS','MYSQL323','MYSQL40','ANSI','NO_AUTO_VALUE_ON_ZERO','NO_B
 
2023-02-24 12:21:54 0 [ERROR] mariadbd: Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
 
2023-02-24 12:21:54 1 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1146: Table 'mysql.gtid_slave_pos' doesn't exist
 
2023-02-24 12:21:54 0 [Note] sql/mariadbd: ready for connections.
 
Version: '11.0.2-MariaDB'  socket: '/tmp/build-mariadb-server-11.0.sock'  port: 0  Source distribution
 
[1]   Done                    sql/mariadbd --no-defaults --skip-networking --datadir=/tmp/${PWD##*/}-datadir --socket=/tmp/${PWD##*/}.sock --plugin-dir=${PWD}/mysql-test/var/plugins/ --verbose
 
2023-02-24 12:21:54 3 [ERROR] InnoDB: Column last_update in table mysql.innodb_table_stats is BINARY(4) NOT NULL but should be INT UNSIGNED NOT NULL
 
2023-02-24 12:21:54 3 [ERROR] InnoDB: Fetch of persistent statistics requested for table `mysql`.`gtid_executed` but the required system tables mysql.innodb_table_stats and mysql.innodb_index_stats are not present or have unexpected structure. Using transient stats instead.
 
2023-02-24 12:21:54 3 [Warning] InnoDB: A transaction id in a record of table `mysql`.`engine_cost` is newer than the system-wide maximum.
 
2023-02-24 12:21:54 3 [ERROR] InnoDB: We detected index corruption in an InnoDB type table. You have to dump + drop + reimport the table or, in a case of widespread corruption, dump all InnoDB tables and recreate the whole tablespace. If the mariadbd server crashes after the startup or when you dump the tables. Please refer to https://mariadb.com/kb/en/library/innodb-recovery-modes/ for information about forcing recovery.
 
2023-02-24 12:21:54 3 [ERROR] mariadbd: Index for table 'engine_cost' is corrupt; try to repair it
 
mariadb-dump: Error 1034: Index for table 'engine_cost' is corrupt; try to repair it when dumping table `engine_cost` at row: 0

Note first startup:

InnoDB: log sequence number 2762352; transaction id 1794

Second startup

2023-02-24 12:21:54 0 [Note] InnoDB: log sequence number 2781972; transaction id 770

Comment by Daniel Black [ 2023-02-24 ]

not-10.11.3-8460eb25d1f897d403136e75b75ef595470d641c

 
2023-02-24 14:03:40 0 [Note] InnoDB: log sequence number 2766763; transaction id 1794

Much more sensible transaction id (same as first startup).

Comment by Thirunarayanan Balathandayuthapani [ 2023-02-24 ]

This problem can happen in 10.11 too if we start the server with --innodb_undo_tablespaces=3
At first(in case of upgrade), we do max trx id from TRX_SYS_TRX_ID_STORE of TRX_SYS page.
In MDEV-19229, InnoDB reset TRX_SYS page and assign rollback segment (1..127) as FIL_NULL ,
frees the existing rollback segment(1..127) of system tablespace. Recreates the specified undo
log tablespace. During next restart, InnoDB fetches the maximum transaction ID from
TRX_UNDO_TRX_ID of 0th rollback segment.

Comment by Marko Mäkelä [ 2023-02-24 ]

I think that a more appropriate place to store the transaction ID is TRX_RSEG_MAX_TRX_ID in rollback segment 0. The upgrade process should also set TRX_RSEG_FORMAT to 0 in that page.

The fields TRX_UNDO_TRX_ID or TRX_UNDO_TRX_NO are transient, referring to active transactions or transactions whose history has not been purged yet. If the undo logs are logically empty, these fields should not be read. That is why TRX_RSEG_MAX_TRX_ID exists.

Comment by Marko Mäkelä [ 2023-03-03 ]

I spent quite a bit of time in an attempt to create a dummy InnoDB system tablespace in Perl code in our regression test suite, but there simply are too many pages in it. I got to the point where dict_sys_t::create_or_check_sys_tables() would crash when trying to create missing data dictionary tables. I could work around it by setting innodb_force_recovery=3, but that will also prevent a change of innodb_undo_tablespaces to take effect. I did not want to add debug injection for this case, and I thought that inserting dummy metadata into the 4 hard-coded system tables for the non-hard-coded system tables in Perl code would be too much effort.

The m57.tar.bz2 can be simplified to a rather small ibdata1.gz like this:

dd if=/dev/zero bs=16384 count=128 seek=64 of=ibdata1 conv=notrunc
 
gzip -9 ibdata1

This will zero out the doublewrite buffer pages. With that file, the problem can be reproduced as follows, starting from an initially empty directory that only contains the file ibdata1.gz:

gunzip ibdata1.gz
 
touch ib_logfile0
 
mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)"
 
mariadbd --innodb-undo-tablespaces=3 --datadir "$(pwd)"

There will be a lot of error messages due to missing files. The relevant part is that the first start-up attempt says the following:

2023-03-03 10:43:57 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2023-03-03 10:43:57 0 [Note] InnoDB: log sequence number 2762352; transaction id 1794

The second start-up attempt will wrongly rewind the transaction ID if the fix is not present:

2023-03-03 10:44:17 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
 
2023-03-03 10:44:17 0 [Note] InnoDB: log sequence number 2786076; transaction id 770

Comment by Marko Mäkelä [ 2023-03-03 ]

For the record, my attempt at a regression test is in 0001-WIP-test-case.patch, against 10.11 8460eb25d1f897d403136e75b75ef595470d641c. It is missing an explicit innodb_undo_tablespaces parameter, so it would not actually execute the MDEV-19229 code. It is hitting some errors in dict_sys_t::create_or_check_sys_tables(). I think that that code should be after the undo log rebuild. With some more effort, could be made a working test, but I think that the time would be better spent on implementing an upgrade test that would catch cases where the LSN or the maximum transaction ID are moving backwards.

I’m mainly attaching the test changes in case we want to improve our robustness of handling corrupted data. In the Perl code, it is rather easy to corrupt specific things.

Generated at Thu Feb 08 10:15:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.