InnoDB Assertion Failure when preparing backup

zergmeister · November 24, 2024, 9:32pm

I am running into an assertion failure when preparing a backup:

2024-11-24 21:23:15 0x7ff1ac4fab80  InnoDB: Assertion failure in thread 140675954748288 in file fsp0fsp.cc line 3891

After which, xtrabackup exits with the following message.

InnoDB: Failing assertion: xdes_mtr_get_bit(descr, XDES_FREE_BIT, header_page % FSP_EXTENT_SIZE, mtr) == FALSE
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
21:23:15 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x3b)[0x55593669b9cb]
xtrabackup(handle_fatal_signal+0x2f1)[0x555936360291]
/lib/x86_64-linux-gnu/libc.so.6(+0x3c050)[0x7ff1aba5b050]
/lib/x86_64-linux-gnu/libc.so.6(+0x8ae3c)[0x7ff1abaa9e3c]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x12)[0x7ff1aba5afb2]
/lib/x86_64-linux-gnu/libc.so.6(abort+0xd3)[0x7ff1aba45472]
xtrabackup(+0x4ff475)[0x555935fd8475]
xtrabackup(+0x51e19e)[0x555935ff719e]
xtrabackup(+0xb9a1f5)[0x5559366731f5]
xtrabackup(_Z8btr_freeRK9page_id_tRK11page_size_t+0x148)[0x555936673708]
xtrabackup(_Z27dict_drop_index_tree_in_memPK12dict_index_tm+0x87)[0x5559366085d7]
xtrabackup(_Z24row_drop_table_for_mysqlPKcP5trx_tbbP12dict_table_t+0x638)[0x555936487eb8]
xtrabackup(_Z26row_mysql_drop_temp_tablesv+0x55a)[0x55593648b18a]
xtrabackup(_Z29recv_recovery_rollback_activev+0x2e)[0x5559364f7c0e]
xtrabackup(_Z34innobase_start_or_create_for_mysqlv+0x3e6b)[0x55593644ebeb]
xtrabackup(+0x5586fe)[0x5559360316fe]
xtrabackup(main+0xd50)[0x555936019fb0]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7ff1aba4624a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7ff1aba46305]
xtrabackup(_start+0x21)[0x5559360305f1]

Please report a bug at https://jira.percona.com/projects/PXB

This is running on Debian 12.7, xtrabackup version 2.4.29.

Any help would be appreciated.

Here is the full output of the --prepare step:

/var/lib/mysql # xtrabackup --prepare --target-dir /var/lib/mysql
xtrabackup: recognized server arguments: --innodb_checksum_algorithm=innodb --innodb_log_checksum_algorithm=innodb --innodb_data_file_path=ibdata1:10M:autoextend --innodb_log_files_in_group=2 --innodb_log_file_size=5242880 --innodb_fast_checksum=0 --innodb_page_size=16384 --innodb_log_block_size=512 --innodb_undo_directory=. --innodb_undo_tablespaces=0 --server-id=1 --redo-log-version=0 
xtrabackup: recognized client arguments: --prepare=1 --target-dir=/var/lib/mysql 
xtrabackup version 2.4.29 based on MySQL server 5.7.44 Linux (x86_64) (revision id: 2e6c0951)
xtrabackup: cd to /var/lib/mysql/
xtrabackup: This target seems to be already prepared.
InnoDB: Number of pools: 1
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = .
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = .
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 5242880
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = .
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = .
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 5242880
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
InnoDB: PUNCH HOLE support available
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Uses event mutexes
InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
InnoDB: Compressed tables use zlib 1.2.13
InnoDB: Number of pools: 1
InnoDB: Using CPU crc32 instructions
InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
InnoDB: Completed initialization of buffer pool
InnoDB: page_cleaner coordinator priority: -20
InnoDB: Highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 18908779862028
InnoDB: Doing recovery: scanned up to log sequence number 18908779862037 (0%)
InnoDB: Database was not shutdown normally!
InnoDB: Starting crash recovery.
InnoDB: pre-5.7.2 rseg: 1 holds data to be purged. History length: 47. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 2 holds data to be purged. History length: 13. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 3 holds data to be purged. History length: 15. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 4 holds data to be purged. History length: 13. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 5 holds data to be purged. History length: 21. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 6 holds data to be purged. History length: 20. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 7 holds data to be purged. History length: 29. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 8 holds data to be purged. History length: 14. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 9 holds data to be purged. History length: 13. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 10 holds data to be purged. History length: 48. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 11 holds data to be purged. History length: 24. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 12 holds data to be purged. History length: 30. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 13 holds data to be purged. History length: 19. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 14 holds data to be purged. History length: 13. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 15 holds data to be purged. History length: 14. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 16 holds data to be purged. History length: 36. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 17 holds data to be purged. History length: 45. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 18 holds data to be purged. History length: 12. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 19 holds data to be purged. History length: 30. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 20 holds data to be purged. History length: 27. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 21 holds data to be purged. History length: 63. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 22 holds data to be purged. History length: 32. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 23 holds data to be purged. History length: 15. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 24 holds data to be purged. History length: 24. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 25 holds data to be purged. History length: 31. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 26 holds data to be purged. History length: 18. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 27 holds data to be purged. History length: 22. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 28 holds data to be purged. History length: 43. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 29 holds data to be purged. History length: 28. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 30 holds data to be purged. History length: 15. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 31 holds data to be purged. History length: 46. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: pre-5.7.2 rseg: 32 holds data to be purged. History length: 43. Recommend slow shutdown with innodb_fast_shutdown=0 and restart
InnoDB: xtrabackup: Last MySQL binlog file position 99367917, file name ./mysql-bin.000009
2024-11-24 21:23:15 0x7ff1ac4fab80  InnoDB: Assertion failure in thread 140675954748288 in file fsp0fsp.cc line 3891
InnoDB: Failing assertion: xdes_mtr_get_bit(descr, XDES_FREE_BIT, header_page % FSP_EXTENT_SIZE, mtr) == FALSE
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
21:23:15 UTC - xtrabackup got signal 6 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x10000
xtrabackup(my_print_stacktrace+0x3b)[0x55593669b9cb]
xtrabackup(handle_fatal_signal+0x2f1)[0x555936360291]
/lib/x86_64-linux-gnu/libc.so.6(+0x3c050)[0x7ff1aba5b050]
/lib/x86_64-linux-gnu/libc.so.6(+0x8ae3c)[0x7ff1abaa9e3c]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x12)[0x7ff1aba5afb2]
/lib/x86_64-linux-gnu/libc.so.6(abort+0xd3)[0x7ff1aba45472]
xtrabackup(+0x4ff475)[0x555935fd8475]
xtrabackup(+0x51e19e)[0x555935ff719e]
xtrabackup(+0xb9a1f5)[0x5559366731f5]
xtrabackup(_Z8btr_freeRK9page_id_tRK11page_size_t+0x148)[0x555936673708]
xtrabackup(_Z27dict_drop_index_tree_in_memPK12dict_index_tm+0x87)[0x5559366085d7]
xtrabackup(_Z24row_drop_table_for_mysqlPKcP5trx_tbbP12dict_table_t+0x638)[0x555936487eb8]
xtrabackup(_Z26row_mysql_drop_temp_tablesv+0x55a)[0x55593648b18a]
xtrabackup(_Z29recv_recovery_rollback_activev+0x2e)[0x5559364f7c0e]
xtrabackup(_Z34innobase_start_or_create_for_mysqlv+0x3e6b)[0x55593644ebeb]
xtrabackup(+0x5586fe)[0x5559360316fe]
xtrabackup(main+0xd50)[0x555936019fb0]
/lib/x86_64-linux-gnu/libc.so.6(+0x2724a)[0x7ff1aba4624a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0x85)[0x7ff1aba46305]
xtrabackup(_start+0x21)[0x5559360305f1]

Please report a bug at https://jira.percona.com/projects/PXB

zergmeister · November 24, 2024, 11:10pm

Additional information. This is the assertion that is failing when preparing:

github.com

percona/percona-xtrabackup/blob/percona-xtrabackup-2.4.29/storage/innobase/fsp/fsp0fsp.cc#L3891


      
          	header_page = page_get_page_no(page_align(header));
          
          	const fil_space_t*	space = mtr_x_lock_space(space_id, mtr);
          	const page_size_t	page_size(space->flags);
          
          	descr = xdes_get_descriptor(space_id, header_page, page_size, mtr);
          
          	/* Check that the header resides on a page which has not been
          	freed yet */
          
          	ut_a(xdes_mtr_get_bit(descr, XDES_FREE_BIT,
          			      header_page % FSP_EXTENT_SIZE, mtr) == FALSE);
          	buf_block_t*		iblock;
          
          	inode = fseg_inode_try_get(header, space_id, page_size, mtr, &iblock);
          
          	if (inode == NULL) {
          		ib::info() << "Double free of inode from "
          			<< page_id_t(space_id, header_page);
          		DBUG_RETURN(TRUE);
          	}

It is the same assertion failure reported on PXB-1963, which failed in the same line

But, unlike in the bug report, tmpdir is not inside datadir, its value is set to /tmp. So not sure what’s happening here.

matthewb · November 26, 2024, 2:00am

Hey @zergmeister,
A couple things: First, that JIRA you referenced hasn’t been updated since November 18, 2019. Second, 5.7 is considered completely end-of-life, meaning no bug fixes, no patches, etc.
Third, we have not released a new version of PXB 2.4 since April 2022 due to 5.7 being EOL. To be honest, it is unlikely this will get fixed.

I would suggest that you follow the output recommendation of PXB and perform a slow shutdown which will purge everything out of InnoDB and produced a cleaned-up undo log. After that, try another backup/prepare and see if the problem resolves itself.

And then after that, focus efforts on upgrading to MySQL 8.0. All Percona engineering efforts are focused on 8.0, 8.4, and 9.* at this time.

zergmeister · November 26, 2024, 2:07am

Hi @matthewb , thanks for the reply.

I agree this issue is probably outside the scope of current efforts. Migrating into MySQL 8.0 is why we’re trying to do a hot backup from this old database with the hopes of avoiding any down time. A slow shutdown might be our only option at this time, albeit with downtime. Will look into that. Thanks again.

matthewb · November 26, 2024, 2:17am

Hey @zergmeister, you might have more success if you stand up a new mysql 8 server, and do a logical dump/restore (depending on the size. If your db is 1TB+, I wouldn’t recommend this approach). Use mydumper/myloader for a faster dump/load process over mysqldump.

If you’re in the cloud, when you slow shut down mysql, take a snapshot of the disk, and build a new mysql server from that, upgrade to 8.0, set up replication, and then cut over when you are ready.

Topic		Replies	Views
Xtrabackup 8.0.14 error while restoring Percona XtraBackup	4	1501	April 22, 2021
SST failing during xtrabackup recovery Percona XtraDB Cluster 5.x	6	1115	December 1, 2016
Bug after restore backup by Xtrabackup Percona XtraBackup	2	863	February 1, 2013
After mysql.5.6.28 upgrade to 8.0.23, percona-xtrabackup-8.0.23 could not be used with mysql 8.0.23 Percona XtraBackup percona	4	1013	June 28, 2021
Xtrabackup is failing once log is applied Percona XtraBackup	5	1707	April 30, 2013

InnoDB Assertion Failure when preparing backup

Related topics