[MDEV-22657] mariabackup prepare --export never finishes Created: 2020-05-21  Updated: 2023-06-25  Resolved: 2023-06-25

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

Type: Bug Priority: Major
Reporter: Eugene Assignee: Marko Mäkelä
Resolution: Incomplete Votes: 1
Labels: None
Environment:

Linux 4.19.121-gentoo x86_64 AMD Opteron(tm) 6376



 Description   

We run galera-based cluster with 3 nodes and considerably large (above 2TB) dataset with lots of small (less then 1GB) databases. Cluster is backed up using mariabackup, so the idea it to use same tool to backup individual databases and restore backup.
Tried to create a backup with

# mariabackup --backup --target-dir=/backup/test/ --innodb-doublewrite --databases='my_database_1'

No issue so far, mariabackup copied files and reported 'Completed OK'.

Next step was attempt to prepare database and try restoring it. Accodring to https://mariadb.com/kb/en/partial-backup-and-restore-with-mariabackup/ tried backup preparation.

# mariabackup --prepare --target-dir=/backup/test/ --export
mariabackup based on MariaDB server 10.4.12-MariaDB Linux (x86_64)
[00] 2020-05-21 13:36:30 mariabackup: auto-enabling --innodb-file-per-table due to the --export option
[00] 2020-05-21 13:36:30 cd to /backup/test/
[00] 2020-05-21 13:36:30 This target seems to be not prepared yet.
[00] 2020-05-21 13:36:30 mariabackup: using the following InnoDB configuration for recovery:
[00] 2020-05-21 13:36:30 innodb_data_home_dir = .
[00] 2020-05-21 13:36:30 innodb_data_file_path = ibdata1:12M:autoextend
[00] 2020-05-21 13:36:30 innodb_log_group_home_dir = .
[00] 2020-05-21 13:36:30 InnoDB: Using Linux native AIO
[00] 2020-05-21 13:36:30 Starting InnoDB instance for recovery.
[00] 2020-05-21 13:36:30 mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
2020-05-21 13:36:30 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-05-21 13:36:30 0 [Note] InnoDB: Uses event mutexes
2020-05-21 13:36:30 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-05-21 13:36:30 0 [Note] InnoDB: Number of pools: 1
2020-05-21 13:36:30 0 [Note] InnoDB: Using SSE2 crc32 instructions
mariabackup: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-05-21 13:36:30 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
2020-05-21 13:36:30 0 [Note] InnoDB: Completed initialization of buffer pool
2020-05-21 13:36:30 0 [Note] InnoDB: page_cleaner coordinator priority: -20
2020-05-21 13:36:30 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=9770703608819
2020-05-21 13:36:31 0 [Note] InnoDB: Tablespace 11385 was not found at './yet_another_database1/query_parameter.ibd', but there were no modifications either.
...
2020-05-21 13:36:31 0 [Note] InnoDB: Tablespace 13964 was not found at './yet_another_database2/trigger_log_event.ibd', but there were no modifications either.
2020-05-21 13:36:31 0 [Note] InnoDB: Tablespace 13974 was not found at './yet_another_database3/webform_log.ibd', but there were no modifications either.
...
2020-05-21 13:36:31 0 [Note] InnoDB: Starting final batch to recover 12050 pages from redo log.
2020-05-21 13:36:31 0 [Note] InnoDB: Last binlog file './mariadb-bin.003700', position 3466
[00] 2020-05-21 13:36:31 Last binlog file ./mariadb-bin.003700, position 3466
[00] 2020-05-21 13:36:31 mariabackup: Recovered WSREP position: 0ca58cd7-****-****-****-23d8****4dfb:174447362
 
[00] 2020-05-21 13:36:33 Prepare export : executing "/usr/bin/mariabackup" --mysqld --defaults-file=./backup-my.cnf --defaults-group-suffix= --datadir=. --innodb --innodb-fast-shutdown=0 --loose-partition --innodb_purge_rseg_truncate_frequency=1 --innodb-buffer-pool-size=104857600 --console  --log-error= --skip-log-bin --bootstrap  < mariabackup_prepare_for_export.sql
 
2020-05-21 13:36:33 0 [Note] mysqld (mysqld 10.4.12-MariaDB) starting as process 15052 ...

However, this process never finish! Previous attempt was stopped after 3 days!

If backup preparation command is modified with omitting '--export', additonal mysql is not started, so backup preparation finishes quickly, but innodb .cfg files are not created.

Attempt to discard and import tablespaces (tried several databases, problem persists) without .cfg files is a lottery that on some tables finishes without any error (just prints a warning about misisng .cfg file) while on others renders into mysqld crash with following error logged:

2020-05-21 13:40:48 14 [ERROR] [FATAL] InnoDB: Trying to read page number 1285 in space 88165, space name my_database_1/contact, which is outside the tablespace bounds. Byte offset 0, len 16384
200521 13:40:48 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. 
...
We think the query pointer is invalid, but we will try to print it anyway. 
Query: ALTER TABLE my_database_1.contact IMPORT TABLESPACE
Writing a core file...

Manual creation with locking tables and copying files on intensively used database is a bad idea, so backup preparation procedure that is executed by mariabackup --prepare --export has an issue, it is normally expected that is finishes with preparing backup and creating .cfg files as described on documentation page.

Additional note. Attempt to run backup preparation on machine that is not configured to run galera and is plain mysql server behaves in same way.



 Comments   
Comment by Marko Mäkelä [ 2022-01-20 ]

euglorg, sorry, I had missed this report.

If you start up the server on the prepared backup, will the table be accessible and would CHECK TABLE report any errors?

If some DDL operation was run on the table while the backup had been created, the failure could be related to that. While Mariabackup already since version 10.2 should not have much trouble with concurrent DDL, DDL operations in the MariaDB Server itself are not crash-safe before version 10.6.

Comment by Eugene [ 2022-02-21 ]

>>> Needs Feedback -> Closed

After paying no attention on the issue for almost two years, you close it as you didn't get a feedback within a month. Brilliant!
Just wonder how many other problems were closed in very same way... Wish people deciding to use mariadb features find this case before they get into the a trouble and think twice before using them...

Now, some facts about the case.
First, the problem is still there, as you guess. Tried to prepare a backup in the very same way it was described initially. The ordinary backup-restore took 12 hours on partial dataset (yes, the database was huge and contained partitions). An attempt to prepare a test-bench with mariabackup ended in 3 weeks when the server was rebooted. Say, there was no reason to wait more as partitioned data retention period is one week while backup preparation took over 3 weeks and didn't finish...
For tiny unpartitioned tables with low server load a procedure of taking a backup, preparing it and restoring it back worked - exactly as it was written in documentation, that's true. But it's usually not a big deal to restore such a database from mysqldump-generated files.
And for the server with a databases of over 100GB of size per database, having partitions and intensively used - an attempt to restore several databases with mariabackup renders in just wasting a time. An attempt to use files that were partially exported when mariabackup was stopped before it finished rendered into mysqld crash on 10.4 - not tested on 10.5, however.

So, in fact mariabackup can't be used for restoring single database from the dataset, the procedure is extremely unreliable. This is practical side of this task resolution.

For those who will find this task later: please consider the fact of necessity for restoring from mysqldump files (with long index creation that can take hours) or necessity of whole dataset replacement in case you would like to rely on mariabackup. For whole dataset mariabackup works perfectly, but for per-database backups this tool can't be used due to the reason mentioned in this task caption.

Comment by Marko Mäkelä [ 2022-02-21 ]

euglorg, thank you for the feedback.

Did you try to specify --use-memory? With a small buffer pool, applying the log will take a long time, and it might actually never finish due to some bugs, such as MDEV-26784.

If you are already assigning a reasonable amount of buffer pool to have the logs applied and it still is slow, could you provide some output of sudo perf top -p $(pgrep mariabackup) to show where the time is being spent?

Note: I expect MDEV-12353 in MariaDB Server 10.5 to speed up the restoring of backups. Before that log format change, the log record parser frequently invoked malloc().

Comment by Eugene [ 2022-02-21 ]

Hello Marko,

We didn't use "--use-memory" option due to MDEV-20679 and MDEV-21222 initially.
This time the command was used without any changes. Will try to check with forced pool size later and let you know (while we'd like to better upgrade to 10.5, we ran into another issue, namely, MDEV-27530 and have had to roll back, so 10.4 will be available for tests for some time).

Comment by Eugene [ 2022-03-29 ]

elenst can I ask you to keep this task open (mean, not close it) for some more time? Due to the war that started recently by russia against Ukraine, all the plans are ruined.

Comment by Marko Mäkelä [ 2022-08-01 ]

euglorg, please check the advice that I posted in MDEV-27530.

Comment by Sergei Golubchik [ 2023-06-25 ]

euglorg, I'm going to close it again. Please, just add a comment whenever you want us to reopen it and we'll do that.

Generated at Thu Feb 08 09:16:27 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.