[MDEV-20679] Mariabackup --prepare runs out of buffer_pool when --use-memory is not default Created: 2019-09-26  Updated: 2021-12-20  Resolved: 2020-02-28

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.4.7
Fix Version/s: 10.2.31, 10.3.22, 10.4.12, 10.5.1

Type: Bug Priority: Major
Reporter: Eugene Assignee: Thirunarayanan Balathandayuthapani
Resolution: Duplicate Votes: 0
Labels: None
Environment:

Linux 4.19.75-gentoo AMD EPYC 7451

Issue Links:
Duplicate
duplicates MDEV-19176 Do not run out of InnoDB buffer pool ... Closed

 Description   

Trying to restore large backup created on the server with heavy load at the moment of backup creation. Backup size is 321GB with ib_logfile0 of 176GB.

Running 

mariabackup --prepare --target-dir=/mnt/mariabackup/

uses 100MB RAM (default) and took already more then 24 hours (while data import from .sql files took 10 hours for this set). Process state changes form S to D and back while CPU load is almost zero, disk utilization is zero (0.1% iowait) and only 100MB RAM is used.

Current behavior:
Attempt to use more memory for backup preparation ends with message like

 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 5129 OS file reads, 0 OS file writes, 0 OS fsyncs.

meaning that mariabackup ran out of innodb buffer pool. However, this pool is much larger then given 'use-memory' option.

In fact, attempts to set use-memory to

  • 1GB
  • 4GB
  • 64GB
  • 128GB (equal to innodb buffer pool size)
  • 224GB
    all ended with same issue (however, percent of process performed was higher for large memory settings, but none of them finished). Preparation process (on second server) running with default parameters is still running (seems to be far from consistent backup state however)

whole output looks like:

# mariabackup --prepare --target-dir=/mnt/mariabackup/ --rebuild_threads=48 --parallel=48 --innodb_buffer_pool_instances=32 --use-memory=4G
 
mariabackup based on MariaDB server 10.4.7-MariaDB Linux (x86_64)
 
[00] 2019-09-26 17:44:09 cd to /mnt/mariabackup/
 
[00] 2019-09-26 17:44:09 This target seems to be not prepared yet.
 
[00] 2019-09-26 17:44:09 mariabackup: using the following InnoDB configuration for recovery:
 
[00] 2019-09-26 17:44:09 innodb_data_home_dir = .
 
[00] 2019-09-26 17:44:09 innodb_data_file_path = ibdata1:12M:autoextend
 
[00] 2019-09-26 17:44:09 innodb_log_group_home_dir = .
 
[00] 2019-09-26 17:44:09 InnoDB: Using Linux native AIO
 
[00] 2019-09-26 17:44:09 Starting InnoDB instance for recovery.
 
[00] 2019-09-26 17:44:09 mariabackup: Using 4294967296 bytes for buffer pool (set by --use-memory parameter)
 
2019-09-26 17:44:09 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2019-09-26 17:44:09 0 [Note] InnoDB: Uses event mutexes
 
2019-09-26 17:44:09 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2019-09-26 17:44:09 0 [Note] InnoDB: Number of pools: 1
 
2019-09-26 17:44:09 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
mariabackup: O_TMPFILE is not supported on /tmp (disabling future attempts)
 
2019-09-26 17:44:09 0 [Note] InnoDB: Initializing buffer pool, total size = 4G, instances = 1, chunk size = 4G
 
2019-09-26 17:44:10 0 [Note] InnoDB: Completed initialization of buffer pool
 
2019-09-26 17:44:10 0 [Note] InnoDB: page_cleaner coordinator priority: -20
 
2019-09-26 17:44:10 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=276915432873
 
2019-09-26 17:44:25 0 [Note] InnoDB: Read redo log up to LSN=257166344192
 
2019-09-26 17:44:40 0 [Note] InnoDB: Read redo log up to LSN=257550057472
 
2019-09-26 17:44:55 0 [Note] InnoDB: Read redo log up to LSN=257930559488
 
2019-09-26 17:45:03 0 [Warning] InnoDB: Difficult to find free blocks in the buffer pool (21 search iterations)! 21 failed attempts to flush a page! Consider increasing innodb_buffer_pool_size. Pending flushes (fsync) log: 0; buffer pool: 0. 20651 OS file reads, 0 OS file writes, 0 OS fsyncs.

MariaDB server has following parameters:

# mariabackup --print-defaults
 
mariabackup would have been started with the following arguments:
 
--interactive_timeout=3600 --log_bin_trust_function_creators=1 --long_query_time=5 --max_allowed_packet=536870912 --log_output=TABLE --max_connections=4000 --slow_launch_time=2 --slow_query_log=0 --wait_timeout=3600 --default_time_zone=Europe/Prague --sql_mode= --character-set-server=utf8 --user=mysql --port=3306 --socket=/var/run/mysqld/mysqld.sock --pid-file=/var/run/mysqld/mariadb.pid --log-error=/var/log/mysql/mysqld.err --basedir=/usr --datadir=/var/lib/mysql --skip-external-locking --lc_messages_dir=/usr/share/mariadb --lc_messages=en_US --bind-address=* --log-bin=mariadb-bin --server-id=3 --tmpdir=/tmp/ --slow_query_log_file=/var/log/mysql/slow_queries.log --binlog_format=ROW --sync_binlog=1 --binlog_cache_size=33554432 --default_storage_engine=innodb --max_connections=512 --sort_buffer_size=2M --read_rnd_buffer_size=2M --table_open_cache=8000 --net_buffer_length=16K --read_buffer_size=2M --open_files_limit=32768 --expire-logs-days=1 --max_binlog_size=1G --key_buffer_size=1G --query_cache_size=0 --query_cache_limit=0 --query_cache_type=0 --thread_cache_size=128 --innodb_buffer_pool_size=128G --innodb_log_buffer_size=2G --innodb_log_file_size=16G --innodb_log_files_in_group=2 --innodb_autoinc_lock_mode=2 --innodb_buffer_pool_instances=32 --innodb_page_cleaners=32 --innodb_lock_wait_timeout=500 --innodb_stats_on_metadata=0 --innodb_numa_interleave=1 --innodb_flush_log_at_trx_commit=2 --innodb_io_capacity_max=8192 --innodb_io_capacity=4096 --innodb-print-all-deadlocks=ON --innodb_write_io_threads=16 --innodb_read_io_threads=16 --innodb_thread_concurrency=0 --innodb_doublewrite=1 --innodb_flush_method=O_DIRECT --performance_schema=ON --performance_schema_instrument=%synch%=on --wsrep_on=FALSE --wsrep_provider=/usr/lib64/galera/libgalera_smm.so --wsrep_provider_options=gcache.size=8G; gcache.page_size=1G; gcs.fc_limit=480; gcs.fc_factor=0.8; gcache.recover=yes --wsrep_cluster_name=se_cluster --wsrep_slave_threads=96

Expected behavior:
According to help page, Mariabackup should use more memory for processing log and preparing backup, thus processing data in memory and much faster.

Additional questions:
Is there any workaround for this?
Is there a way to speed up backup preparation process?

 Comments   
Comment by Elena Stepanova [ 2019-10-06 ]

There is a still open issue MDEV-19176, possibly it's the same problem. Assigning to marko to judge on that.

Comment by Marko Mäkelä [ 2019-10-07 ]

I confirm that this is essentially a duplicate of MDEV-19176.

Comment by Geoff Montee (Inactive) [ 2020-02-28 ]

Should this bug be closed now that MDEV-19176 has been fixed, or does it still require more work to fix the mariabackup part?

Comment by Marko Mäkelä [ 2020-02-28 ]

The similar bug MDEV-21222 is still open. I have seen that type of failures on buildbot every now and then, at least on the 10.5 branch, but likely also on older versions.

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