[MDEV-19401] mariabackup stuck when running apply-log-only with export Created: 2019-05-06  Updated: 2023-12-14

Status: Open
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.3.12
Fix Version/s: 10.3

Type: Bug Priority: Major
Reporter: Carlos Rubio Assignee: Vladislav Lesin
Resolution: Unresolved Votes: 1
Labels: None
Environment:

ubuntu 18.04


 Description   

when we update to mariadb 10.2.21 we where forced to upgrade to mariabackup 10.3.12 to get backups working. since then sometimes the backup process get stuck when we tried to export the cfg files.

First we prepare the backup

root@backupmysql:/Respaldo/base_sitio_nuevo# mariabackup --prepare --apply-log-only --verbose --target-dir=/Respaldo/base_sitio_nuevo/20190505
mariabackup: cd to /Respaldo/base_sitio_nuevo/20190505/
mariabackup: This target seems to be not prepared yet.
mariabackup: using the following InnoDB configuration for recovery:
mariabackup: innodb_data_home_dir = .
mariabackup: innodb_data_file_path = ibdata1:5000M;ibdata2:100M:autoextend
mariabackup: innodb_log_group_home_dir = .
2019-05-05 05:39:09 0x7f71bb26b7c0 InnoDB: Using Linux native AIO
mariabackup: Starting InnoDB instance for recovery.
mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
2019-05-05 5:39:09 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-05-05 5:39:09 0 [Note] InnoDB: Uses event mutexes
2019-05-05 5:39:09 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-05-05 5:39:09 0 [Note] InnoDB: Number of pools: 1
2019-05-05 5:39:09 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-05-05 5:39:09 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
2019-05-05 5:39:09 0 [Note] InnoDB: Completed initialization of buffer pool
2019-05-05 5:39:09 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-05-05 5:39:09 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=7194495242963
MLOG_CHECKPOINT(7194495242963) read at 7194495242972
......
......
apply 7194516842523: 38 len 16 page 26515:2241208
Applying log to page 13958:166287
Applying log to page 13958:399878
2019-05-05 5:39:22 0 [Note] InnoDB: Last binlog file '/DATA/mysql_binlog/mariadb-bin.000192', position 312402516
Last binlog file /DATA/mysql_binlog/mariadb-bin.000192, position 312402516

Then we export the cfg files

root@backupmysql:/Respaldo/base_sitio_nuevo# mariabackup --prepare --apply-log-only --export --target-dir=/Respaldo/base_sitio_nuevo/20190505
mariabackup based on MariaDB server 10.3.12-MariaDB debian-linux-gnu (x86_64)
mariabackup: auto-enabling --innodb-file-per-table due to the --export option
mariabackup: cd to /Respaldo/base_sitio_nuevo/20190505/
mariabackup: This target seems to be already prepared.
mariabackup: using the following InnoDB configuration for recovery:
mariabackup: innodb_data_home_dir = .
mariabackup: innodb_data_file_path = ibdata1:5000M;ibdata2:100M:autoextend
mariabackup: innodb_log_group_home_dir = .
2019-05-06 14:00:04 0x7f46eadb77c0 InnoDB: Using Linux native AIO
mariabackup: Starting InnoDB instance for recovery.
mariabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
2019-05-06 14:00:04 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-05-06 14:00:04 0 [Note] InnoDB: Uses event mutexes
2019-05-06 14:00:04 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-05-06 14:00:04 0 [Note] InnoDB: Number of pools: 1
2019-05-06 14:00:04 0 [Note] InnoDB: Using SSE2 crc32 instructions
2019-05-06 14:00:04 0 [Note] InnoDB: Initializing buffer pool, total size = 100M, instances = 1, chunk size = 100M
2019-05-06 14:00:04 0 [Note] InnoDB: Completed initialization of buffer pool
2019-05-06 14:00:04 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2019-05-06 14:00:04 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=7194517173825
2019-05-06 14:00:04 0 [Note] InnoDB: Last binlog file '/DATA/mysql_binlog/mariadb-bin.000192', position 312402516
Last binlog file /DATA/mysql_binlog/mariadb-bin.000192, position 312402516
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= --bootstrap < mariabackup_prepare_for_export.sql
2019-05-06 14:00:05 0 [Note] mysqld (mysqld 10.3.12-MariaDB-1:10.3.12+maria~bionic) starting as process 29 ...

And the process get stuck here forever, also using high cpu with 4 cores running wild

 Comments   
Comment by Marko Mäkelä [ 2023-12-14 ]

Calculating from the output, the backup applied about 21,599,560 bytes of log records (7194516842523-7194495242963), which is not that much.

Note that the mariabackup or mariadb-backup by default behaves as if --apply-log-only had been specified. The only occasion where mariadb-backup is generating InnoDB redo log records on its own is when it is exporting tablespaces. It needs to be able to roll back any incomplete transactions and merge any pending changes from the change buffer.

So, you have specified incompatible options. Instead of hanging or getting into a busy loop, mariadb-backup should return an error straight from the beginning.

Generated at Thu Feb 08 08:51:24 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.