[MDEV-31410] mariadb-backup prepare crash with InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT Created: 2023-06-06  Updated: 2023-10-12  Resolved: 2023-10-12

Status: Closed
Project: MariaDB Server
Component/s: Backup, mariabackup, Storage Engine - InnoDB
Affects Version/s: 10.11.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Vladimir Votyakov Assignee: Marko Mäkelä
Resolution: Duplicate Votes: 0
Labels: backup, bug, innodb, upgrade
Environment:

Debian 11


Issue Links:
Duplicate
duplicates MDEV-19492 Mariabackup hangs if table populated ... Stalled
Relates
relates to MDEV-28870 InnoDB: Missing FILE_CREATE, FILE_DEL... Closed
relates to MDEV-30000 make mariadb-backup to force an innod... Open

 Description   

After upgrade from 10.3.4 to 10.11.3, mariabackup gives error on backup prepare stage.

I am doing a partial backup using the --databases='mysql database_mail' argument and tablespace 1296 (database_log) should not be included in the backup.

Also worth noting, if I backup another database (--databases='mysql database_common'), all is well.

There are no errors or warnings during the backup process.

Full log:

mariabackup based on MariaDB server 10.11.3-MariaDB debian-linux-gnu (x86_64)
[00] 2023-06-05 06:58:50 cd to /backup/
[00] 2023-06-05 06:58:50 open files limit requested 0, set to 1048576
[00] 2023-06-05 06:58:50 This target seems to be not prepared yet.
[00] 2023-06-05 06:58:50 mariabackup: using the following InnoDB configuration for recovery:
[00] 2023-06-05 06:58:50 innodb_data_home_dir = .
[00] 2023-06-05 06:58:50 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2023-06-05 06:58:50 innodb_log_group_home_dir = .
[00] 2023-06-05 06:58:50 InnoDB: Using liburing
[00] 2023-06-05 06:58:50 Starting InnoDB instance for recovery.
[00] 2023-06-05 06:58:50 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
2023-06-05  6:58:50 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-06-05  6:58:50 0 [Note] InnoDB: Number of transaction pools: 1
2023-06-05  6:58:50 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-06-05  6:58:50 0 [Note] InnoDB: Using liburing
2023-06-05  6:58:50 0 [Note] InnoDB: Initializing buffer pool, total size = 100.000MiB, chunk size = 100.000MiB
2023-06-05  6:58:50 0 [Note] InnoDB: Completed initialization of buffer pool
2023-06-05  6:58:50 0 [Note] InnoDB: Buffered log writes (block size=4096 bytes)
2023-06-05  6:58:50 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=6957562626620
2023-06-05  6:58:57 0 [ERROR] InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT for tablespace 1296
[00] 2023-06-05 06:58:57 mariadb-backup: srv_start() returned 37 (Data structure corruption).

mariabackup --print-defaults:

--default_storage_engine=InnoDB --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306 --basedir=/usr --datadir=/var/lib/mysql --tmpdir=/tmp --lc_messages_dir=/usr/share/mysql --lc_messages=en_US --bind-address=0.0.0.0 --skip-external-locking --skip-name-resolve --max_connections=3500 --connect_timeout=5 --wait_timeout=600 --max_allowed_packet=32M --thread_cache_size=256 --sort_buffer_size=8M --bulk_insert_buffer_size=32M --tmp_table_size=64M --max_heap_table_size=64M --log_warnings=2 --slow_query_log=1 --slow_query_log_file=/var/log/mysql/mariadb-slow.log --long_query_time=10 --log_slow_verbosity=query_plan --log_bin=/var/log/mysql/mariadb-bin --log_bin_index=/var/log/mysql/mariadb-bin.index --relay-log=/var/log/mysql/mariadb-relay-bin --relay_log_space_limit=100G --sync_binlog=0 --expire_logs_days=3 --max_binlog_size=100M --query_cache_limit=128K --query_cache_size=512M --character-set-server=utf8mb4 --collation-server=utf8mb4_general_ci --innodb_force_recovery=0 --slave-skip-errors=1062 --innodb_log_file_size=16G --innodb_buffer_pool_size=16384M --innodb_log_buffer_size=16M --innodb_file_per_table=1 --innodb_open_files=800 --innodb_io_capacity=800 --innodb_flush_method=O_DIRECT --innodb_flush_log_at_trx_commit=0 --binlog-do-db=database_log --region.replicate-do-db=database_log --game_region.replicate-do-db=database_mail --harbor.replicate-do-db=database_common --replicate-ignore-table=database_log.log --server-id=224 --myisam_recover_options=BACKUP --key_buffer_size=128M --myisam_sort_buffer_size=512M --table_open_cache=400 --concurrent_insert=2 --read_buffer_size=2M --read_rnd_buffer_size=1M



 Comments   
Comment by Marko Mäkelä [ 2023-06-06 ]

I see no crash, but an error return due to corruption that was noticed while restoring a backup.

This might be a duplicate of MDEV-19492, that is, the backup could not keep up with the log writing rate of the server. Due to the log file format change in MDEV-14425, the diagnostics for log file overrun is very limited. (A log block sequence number was shrunk to 1 bit.)

Can you post the output of mariadb-backup --backup that preceded the failed prepare? Both need to be from the same run. Which innodb_log_file_size and innodb_buffer_pool_size is the server using?

Comment by Vladimir Votyakov [ 2023-06-06 ]

Yeah it's error, sorry for mistake.

innodb_log_file_size=16G
innodb_buffer_pool_size=16384M

Full log:

[00] 2023-06-06 10:27:16 Connecting to MariaDB server host: localhost, user: root, password: not set, port: not set, socket: /var/run/mysqld/mysqld.sock
[00] 2023-06-06 10:27:16 Using server version 10.11.3-MariaDB-1:10.11.3+maria~deb11-log
/root/mariadb-10.11.3-linux-systemd-x86_64/bin/mariadb-backup based on MariaDB server 10.11.3-MariaDB linux-systemd (x86_64)
[00] 2023-06-06 10:27:16 uses posix_fadvise().
[00] 2023-06-06 10:27:16 cd to /var/lib/mysql/
[00] 2023-06-06 10:27:16 open files limit requested 0, set to 1048576
[00] 2023-06-06 10:27:16 mariabackup: using the following InnoDB configuration:
[00] 2023-06-06 10:27:16 innodb_data_home_dir =
[00] 2023-06-06 10:27:16 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2023-06-06 10:27:16 innodb_log_group_home_dir = ./
[00] 2023-06-06 10:27:16 InnoDB: Using Linux native AIO
2023-06-06 10:27:16 0 [Note] InnoDB: Number of transaction pools: 1
2023-06-06 10:27:16 0 [Note] InnoDB: Buffered log writes (block size=4096 bytes)
[00] 2023-06-06 10:27:16 mariabackup: Generating a list of tablespaces
Skipping db: ./database_log
Skipping db: ./sys
Skipping db: ./database_analytics
Skipping db: ./database_ex
Skipping db: ./database_common
Skipping db: ./performance_schema
[01] 2023-06-06 10:27:16 Copying ./mysql/innodb_index_stats.ibd to /root/temp/mysql/innodb_index_stats.ibd
[01] 2023-06-06 10:27:16         ...done
[01] 2023-06-06 10:27:16 Copying ./mysql/gtid_slave_pos.ibd to /root/temp/mysql/gtid_slave_pos.ibd
[01] 2023-06-06 10:27:16         ...done
[01] 2023-06-06 10:27:16 Copying ./mysql/transaction_registry.ibd to /root/temp/mysql/transaction_registry.ibd
[01] 2023-06-06 10:27:16         ...done
[01] 2023-06-06 10:27:16 Copying ./mysql/innodb_table_stats.ibd to /root/temp/mysql/innodb_table_stats.ibd
[01] 2023-06-06 10:27:16         ...done
[01] 2023-06-06 10:27:16 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:16         ...done
[01] 2023-06-06 10:27:16 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:24         ...done
[01] 2023-06-06 10:27:24 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ./database_mail/some_table.ibd to /root/temp/database_mail/some_table.ibd
[01] 2023-06-06 10:27:36         ...done
[01] 2023-06-06 10:27:36 Copying ibdata1 to /root/temp/ibdata1
[01] 2023-06-06 10:27:37         ...done
[00] 2023-06-06 10:27:37 Acquiring BACKUP LOCKS...
[00] 2023-06-06 10:27:37 Starting to backup non-InnoDB tables and files
[00] 2023-06-06 10:27:37 Skipping db: ./database_log
[01] 2023-06-06 10:27:37 Copying ./mysql/tables_priv.MAI to /root/temp/mysql/tables_priv.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/general_log.frm to /root/temp/mysql/general_log.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/func.MAD to /root/temp/mysql/func.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/func.frm to /root/temp/mysql/func.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_name.frm to /root/temp/mysql/time_zone_name.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/roles_mapping.MAI to /root/temp/mysql/roles_mapping.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/gtid_slave_pos.frm to /root/temp/mysql/gtid_slave_pos.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/transaction_registry.frm to /root/temp/mysql/transaction_registry.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proxies_priv.frm to /root/temp/mysql/proxies_priv.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/db.opt to /root/temp/mysql/db.opt
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_name.MAD to /root/temp/mysql/time_zone_name.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/innodb_table_stats.frm to /root/temp/mysql/innodb_table_stats.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_topic.MAI to /root/temp/mysql/help_topic.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/procs_priv.MAD to /root/temp/mysql/procs_priv.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/servers.frm to /root/temp/mysql/servers.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/index_stats.MAI to /root/temp/mysql/index_stats.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/columns_priv.frm to /root/temp/mysql/columns_priv.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/slow_log.frm to /root/temp/mysql/slow_log.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_category.frm to /root/temp/mysql/help_category.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/table_stats.MAI to /root/temp/mysql/table_stats.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/slow_log.CSV to /root/temp/mysql/slow_log.CSV
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/global_priv.MAD to /root/temp/mysql/global_priv.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/tables_priv.MAD to /root/temp/mysql/tables_priv.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proc.MAD to /root/temp/mysql/proc.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition.frm to /root/temp/mysql/time_zone_transition.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/table_stats.MAD to /root/temp/mysql/table_stats.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_topic.frm to /root/temp/mysql/help_topic.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_relation.frm to /root/temp/mysql/help_relation.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proxies_priv.MAI to /root/temp/mysql/proxies_priv.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/table_stats.frm to /root/temp/mysql/table_stats.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/plugin.frm to /root/temp/mysql/plugin.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_keyword.MAI to /root/temp/mysql/help_keyword.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proc.frm to /root/temp/mysql/proc.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/event.MAI to /root/temp/mysql/event.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/procs_priv.MAI to /root/temp/mysql/procs_priv.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_keyword.frm to /root/temp/mysql/help_keyword.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/plugin.MAI to /root/temp/mysql/plugin.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition.MAD to /root/temp/mysql/time_zone_transition.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone.frm to /root/temp/mysql/time_zone.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/global_priv.MAI to /root/temp/mysql/global_priv.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_keyword.MAD to /root/temp/mysql/help_keyword.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/procs_priv.frm to /root/temp/mysql/procs_priv.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/tables_priv.frm to /root/temp/mysql/tables_priv.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/columns_priv.MAD to /root/temp/mysql/columns_priv.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/servers.MAI to /root/temp/mysql/servers.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/slow_log.CSM to /root/temp/mysql/slow_log.CSM
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/column_stats.MAD to /root/temp/mysql/column_stats.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition_type.MAD to /root/temp/mysql/time_zone_transition_type.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/event.MAD to /root/temp/mysql/event.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_topic.MAD to /root/temp/mysql/help_topic.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_category.MAI to /root/temp/mysql/help_category.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/general_log.CSV to /root/temp/mysql/general_log.CSV
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/innodb_index_stats.frm to /root/temp/mysql/innodb_index_stats.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition_type.frm to /root/temp/mysql/time_zone_transition_type.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/event.frm to /root/temp/mysql/event.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/servers.MAD to /root/temp/mysql/servers.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/db.frm to /root/temp/mysql/db.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/db.MAI to /root/temp/mysql/db.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/column_stats.frm to /root/temp/mysql/column_stats.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/columns_priv.MAI to /root/temp/mysql/columns_priv.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_relation.MAI to /root/temp/mysql/help_relation.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/plugin.MAD to /root/temp/mysql/plugin.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/index_stats.MAD to /root/temp/mysql/index_stats.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_leap_second.MAI to /root/temp/mysql/time_zone_leap_second.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/general_log.CSM to /root/temp/mysql/general_log.CSM
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/db.MAD to /root/temp/mysql/db.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proc.MAI to /root/temp/mysql/proc.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/user.frm to /root/temp/mysql/user.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone.MAD to /root/temp/mysql/time_zone.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/roles_mapping.MAD to /root/temp/mysql/roles_mapping.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_leap_second.frm to /root/temp/mysql/time_zone_leap_second.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_relation.MAD to /root/temp/mysql/help_relation.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/func.MAI to /root/temp/mysql/func.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition.MAI to /root/temp/mysql/time_zone_transition.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_leap_second.MAD to /root/temp/mysql/time_zone_leap_second.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_transition_type.MAI to /root/temp/mysql/time_zone_transition_type.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone_name.MAI to /root/temp/mysql/time_zone_name.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/help_category.MAD to /root/temp/mysql/help_category.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/global_priv.frm to /root/temp/mysql/global_priv.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/proxies_priv.MAD to /root/temp/mysql/proxies_priv.MAD
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/time_zone.MAI to /root/temp/mysql/time_zone.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/column_stats.MAI to /root/temp/mysql/column_stats.MAI
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/roles_mapping.frm to /root/temp/mysql/roles_mapping.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./mysql/index_stats.frm to /root/temp/mysql/index_stats.frm
[01] 2023-06-06 10:27:37         ...done
[00] 2023-06-06 10:27:37 Skipping db: ./sys
[00] 2023-06-06 10:27:37 Skipping db: ./database_analytics
[00] 2023-06-06 10:27:37 Skipping db: ./database_ex
[00] 2023-06-06 10:27:37 Skipping db: ./database_common
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/db.opt to /root/temp/database_mail/db.opt
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying ./database_mail/some_table.frm to /root/temp/database_mail/some_table.frm
[01] 2023-06-06 10:27:37         ...done
[00] 2023-06-06 10:27:37 Skipping db: ./performance_schema
[00] 2023-06-06 10:27:37 Finished backing up non-InnoDB tables and files
[01] 2023-06-06 10:27:37 Copying /var/lib/mysql//aria_log.00000001 to /root/temp/aria_log.00000001
[01] 2023-06-06 10:27:37         ...done
[01] 2023-06-06 10:27:37 Copying /var/lib/mysql//aria_log_control to /root/temp/aria_log_control
[01] 2023-06-06 10:27:37         ...done
[00] 2023-06-06 10:27:37 Waiting for log copy thread to read lsn 6992103029800
[00] 2023-06-06 10:32:31 Writing xtrabackup_binlog_info
[00] 2023-06-06 10:32:31         ...done
[00] 2023-06-06 10:32:31 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
[00] 2023-06-06 10:32:31 mariabackup: The latest check point (for incremental): '6986900819925'
mariabackup: Stopping log copying thread.
[00] 2023-06-06 10:32:32 Executing BACKUP STAGE END
[00] 2023-06-06 10:32:32 All tables unlocked
[00] 2023-06-06 10:32:32 Backup created in directory '/root/temp/'
[00] 2023-06-06 10:32:32 MySQL binlog position: filename 'mariadb-bin.001710', position '68452654', GTID of the last change '0-12-2918953275'
[00] 2023-06-06 10:32:32 Writing backup-my.cnf
[00] 2023-06-06 10:32:32         ...done
[00] 2023-06-06 10:32:32 Writing xtrabackup_info
[00] 2023-06-06 10:32:32         ...done
[00] 2023-06-06 10:32:32 Redo log (from LSN 6986900819925 to 6992103054363) was copied.
[00] 2023-06-06 10:32:32 completed OK!
/root/mariadb-10.11.3-linux-systemd-x86_64/bin/mariadb-backup based on MariaDB server 10.11.3-MariaDB linux-systemd (x86_64)
[00] 2023-06-06 10:32:32 cd to /root/temp/
[00] 2023-06-06 10:32:32 open files limit requested 0, set to 1048576
[00] 2023-06-06 10:32:32 This target seems to be not prepared yet.
[00] 2023-06-06 10:32:32 mariabackup: using the following InnoDB configuration for recovery:
[00] 2023-06-06 10:32:32 innodb_data_home_dir = .
[00] 2023-06-06 10:32:32 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2023-06-06 10:32:32 innodb_log_group_home_dir = .
[00] 2023-06-06 10:32:32 InnoDB: Using Linux native AIO
[00] 2023-06-06 10:32:32 Starting InnoDB instance for recovery.
[00] 2023-06-06 10:32:32 mariabackup: Using 17179869184 bytes for buffer pool (set by --use-memory parameter)
2023-06-06 10:32:32 0 [Note] InnoDB: Compressed tables use zlib 1.2.13
2023-06-06 10:32:32 0 [Note] InnoDB: Number of transaction pools: 1
2023-06-06 10:32:32 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-06-06 10:32:32 0 [Note] InnoDB: Using Linux native AIO
2023-06-06 10:32:32 0 [Note] InnoDB: Initializing buffer pool, total size = 16.000GiB, chunk size = 16.000GiB
2023-06-06 10:32:32 0 [Note] InnoDB: Completed initialization of buffer pool
2023-06-06 10:32:32 0 [Note] InnoDB: Buffered log writes (block size=4096 bytes)
2023-06-06 10:32:32 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=6986900819925
2023-06-06 10:32:42 0 [ERROR] InnoDB: Missing FILE_CREATE, FILE_DELETE or FILE_MODIFY before FILE_CHECKPOINT for tablespace 1257
[00] 2023-06-06 10:32:42 mariadb-backup: srv_start() returned 37 (Data structure corruption).

I needed to change all table names to "some_table" due to NDA.

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

Thank you. The log file size definitely does not look too small. The LSN difference in

[00] 2023-06-06 10:32:32 Redo log (from LSN 6986900819925 to 6992103054363) was copied.

is 5,202,234,438 bytes (4.84 GiB). Because your innodb_log_file_size is much larger than that, there certainly can’t have been any log file overrun.

Unfortunately, it is practically impossible to diagnose or fix this without having a way to reproduce the failure. Our internal stress testing does cover crash recovery and backup, and we try to fix any bugs as soon as possible. When we have rr replay traces of both the server that produced the log and the recovery that led to failure, things are rather easy to diagnose and fix.

I am aware of one hard-to-reproduce recovery failure that probably affects 10.8 and later releases, and despite the error message being different, it might share a root cause with this failure. I uploaded an example of that to MDEV-31353. Sadly, we have no rr replay trace of that yet.

I believe that this bug can be worked around by doing what is suggested in MDEV-30000. I am yet to implement that suggestion in our code base.

Comment by Vladimir Votyakov [ 2023-06-06 ]

My bug reproduces stably. Is there a tutorial on how to do a rr trace correctly?

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

In my experience, rr replay traces are not portable between different CPU microarchitectures or perhaps even Linux kernel versions, so a subsequent analysis would likely require remote access to a system that generated the trace.

A reproducible test case that uses artificial data would probably be more practical.

Comment by Stephan Vos [ 2023-06-14 ]

@Marko
"[00] 2023-06-06 10:32:32 Redo log (from LSN 6986900819925 to 6992103054363) was copied."

Does this mean that if the delta of LSN is bigger than the innodb_log_file_size it was overrun?
I did some calculations of my backups and it sometimes exceeds 2GB (which is our log file size) but no errors during the backup.

Comment by Vladimir Votyakov [ 2023-07-20 ]

@Marko Mäkelä any chance of a fix?
Still reproduces stably on 10.11.4

Comment by Marko Mäkelä [ 2023-09-18 ]

I believe that an actual fix of this would be to reimplement backup (MDEV-14992) so that the server will be responsible for copying the log.

stephanvos, yes, if the server is busy writing InnoDB log, the circular ib_logfile0 may be overwritten several times while backup is running. Backup could also fail to catch up with the log-writing rate. In the MDEV-14425 log format, I do not think that there is there is no way to provide any more accurate diagnostics about this.

Beshelmek, there are two possible work-arounds: use a larger innodb_log_file_size (note: if you SET GLOBAL innodb_log_file_size while backup is running, the backup will never finish, because it will not be able to switch to the rebuilt log file on the fly), or try SET GLOBAL innodb_log_file_buffering=ON before starting the backup so that the writes by the mariadbd server can be read by mariadb-backup --backup via the file system cache.

Would either of these work-arounds work for you?

Comment by Vladimir Votyakov [ 2023-09-18 ]

@Marko Mäkelä , another workaround worked for me

I made a procedure for cleaning InnoDB dirty pages and I call it before every backup, works stably

BEGIN
    DECLARE c INT DEFAULT 30;
    DECLARE pct FLOAT;
    DECLARE pct_lwm FLOAT;
 
    -- Initialize variables
    SET pct = @@GLOBAL.innodb_max_dirty_pages_pct;
    SET pct_lwm = @@GLOBAL.innodb_max_dirty_pages_pct_lwm;
 
    -- Temporarily set InnoDB parameters to flush dirty pages
    SET @@GLOBAL.innodb_max_dirty_pages_pct = 0;
    SET @@GLOBAL.innodb_max_dirty_pages_pct_lwm = 0;
 
    -- Loop until dirty pages are flushed or timeout reached
    WHILE (1 IN (SELECT variable_value > 0 FROM information_schema.global_status WHERE variable_name='INNODB_BUFFER_POOL_PAGES_DIRTY') AND c > 0) DO
        DO SLEEP(1);
        SET c = c - 1;
    END WHILE;
 
    -- Restore original InnoDB parameters
    SET @@GLOBAL.innodb_max_dirty_pages_pct = pct;
    SET @@GLOBAL.innodb_max_dirty_pages_pct_lwm = pct_lwm;
END

Comment by Vladimir Votyakov [ 2023-09-18 ]

I will try workaround with innodb_log_file_size/innodb_log_file_buffering a bit later and I'll give you feedback

Comment by Marko Mäkelä [ 2023-09-21 ]

Beshelmek, thank you, that script should be made unnecessary when MDEV-30000 is eventually implemented.

Comment by Marko Mäkelä [ 2023-10-06 ]

stephanvos, did these suggestions work for you?

Comment by Stephan Vos [ 2023-10-11 ]

Marko, I doubled innodb_log_file_size from 2GB to 4GB and so far it seems to have fixed the issue.

Comment by Marko Mäkelä [ 2023-10-12 ]

stephanvos, thank you. I read somewhere that on a recommended value for innodb_log_file_size would correspond to the LSN growth during 1 hour of operation.

If storage space is not an issue, I would consider making innodb_log_file_size at least innodb_buffer_pool_size or even a multiple of that. In MDEV-29911 the memory usage and the performance of crash recovery were improved.

Comment by Marko Mäkelä [ 2023-10-12 ]

This report pretty much duplicates the design problem MDEV-19492, which could end up being fixed in MDEV-14992.

Comment by Stephan Vos [ 2023-10-12 ]

Thanks Marko.
Our innodb_buffer_pool_size = 464GB so would not be an option to set log to that size or bigger.
I will use your suggestion of LSN to see what it is for an hour.
Are you saying crash recovery wont take as long anymore with a big log buffer?

Comment by Marko Mäkelä [ 2023-10-12 ]

stephanvos, I have written down some notes from my testing of MDEV-29911. The main improvements were as follows:

  • We use almost all of the buffer pool for caching the parsed log records, so that recovery can be done in a single batch in more cases.
  • In case data pages can be recovered based on the log records alone (MDEV-12699), we will invoke a “fake read callback” in a separate thread, just like we would do when the pages would actually have to be read. This makes recovery multi-threaded for such scenarios.
Generated at Thu Feb 08 10:23:40 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.