[MDEV-27326] Mariabackup being overwhelmed during the prepare phase while using 32GB of memory Created: 2021-12-20  Updated: 2022-04-05  Resolved: 2022-04-05

Status: Closed
Project: MariaDB Server
Component/s: Backup, Documentation
Affects Version/s: 10.2.27
Fix Version/s: N/A

Type: Bug Priority: Critical
Reporter: Scott Sommerville (Inactive) Assignee: Geoff Montee (Inactive)
Resolution: Fixed Votes: 1
Labels: None
Environment:

RHEL

Attachments: Text File gdb-thread-dump-output-20211019_034935.txt     Text File gdb-thread-dump-output-20211019_035107.txt     Text File gdb-thread-dump-output-20211019_035225.txt     Text File gdb-thread-dump-output-20211019_035242.txt     File restore.2021-10-08_1820332.customer_3400_db170011_s_2021-10-08_0612271.log    
Issue Links:
Relates
relates to MDEV-19586 Replace recv_sys_t::addr_hash with a ... Closed
relates to MDEV-21351 Replace recv_sys.heap with list of bu... Closed
relates to MDEV-26784 [Warning] InnoDB: Difficult to find f... Closed

 Description   

During the restore step the customer was getting "Restore failed on 10.2.27 with signal 6 and 11"

Oct 9 08:19:43 db166020 kernel: [5710622.181729] mariabackup[143845]: segfault at 0 ip 0000561e04a2dc88 sp 00007f2b853d97f0 error 6 in mariabackup[561e041da000+913000]

Below is the stack trace from the mariabackup output:

2021-10-09  8:19:42 139824895743744 [ERROR] [FATAL] InnoDB: is_short 0, info_and_status_bits 0, offset 10140, o_offset 9, mismatch index 18446744073709551594, end_seg_len 31 pars
 
ed len 3
 
211009  8:19:42 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed,
 
something is definitely wrong and this may fail.
 
 
Server version: 10.2.27-MariaDB
 
key_buffer_size=0
 
read_buffer_size=131072
 
max_used_connections=0
 
max_threads=1
 
thread_count=0
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5419 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
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 = 0x0 thread_stack 0x49000
 
/glide/mariadb/10.2.27snc2/bin/mariabackup(my_print_stacktrace+0x2e)[0x561e04a30c7e]
 
mysys/stacktrace.c:268(my_print_stacktrace)[0x561e044d554d]
 
sigaction.c:0(__restore_rt)[0x7f3412b5e630]
 
:0(__GI_raise)[0x7f3411968387]
 
:0(__GI_abort)[0x7f3411969a78]
 
ut/ut0ut.cc:645(ib::fatal::~fatal())[0x561e0482e823]
 
page/page0cur.cc:1200(page_cur_parse_insert_rec(unsigned long, unsigned char const*, unsigned char const*, buf_block_t*, dict_index_t*, mtr_t*))[0x561e0474df9b]
 
log/log0recv.cc:1655(recv_parse_or_apply_log_rec_body(mlog_id_t, unsigned char*, unsigned char*, unsigned long, unsigned long, bool, buf_block_t*, mtr_t*))[0x561e0472c1d1]
 
log/log0recv.cc:2162(recv_recover_page(buf_block_t*, mtr_t&, recv_addr_t*, unsigned long))[0x561e0472ce19]
 
log/log0recv.cc:2272(recv_recover_page(buf_page_t*))[0x561e041eb78d]
 
buf/buf0buf.cc:6164(buf_page_io_complete(buf_page_t*, bool, bool))[0x561e0461eb9c]
 
fil/fil0fil.cc:5169(fil_aio_wait(unsigned long))[0x561e0466c461]
 
srv/srv0start.cc:331(io_handler_thread)[0x561e047e0da8]
 
pthread_create.c:0(start_thread)[0x7f3412b56ea5]
 
/lib64/libc.so.6(clone+0x6d)[0x7f3411a309fd]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file...
 
Working directory at /glide/mysqld/customecert_3400_peta/temp/restore_2021-10-08_1820332/customer_3400_db170011_s_2021-10-08_0612271
 
Resource Limits:
 
Fatal signal 11 while backtracing

The customer managed to capture thread dumps and the mariabakcup log, which I have attached to this ticket.

Unfortunately, there was no cored dump capture during said event.

Furthermore, the customer was able to avoid the mariabackup crash during the restore by increasing the previously sizeable "--use-memory" of 32GB to 256GB. However they did not see the following log:

[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.

Therefore, it does not seem related to https://jira.mariadb.org/browse/MDEV-20679 as I had initially hoped.

If you require any other information, please let us know.

 Comments   
Comment by Marko Mäkelä [ 2022-02-17 ]

Before MDEV-19586, MDEV-21351, and MDEV-26784 and possibly other changes in MariaDB Server 10.5, recovery as well as mariadb-backup --prepare may run out of memory. The intended behaviour is to reserve at most ⅓ of the buffer pool for buffered log records.

Porting MDEV-21351 from 10.5 to earlier versions is highly nontrivial.

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

The mariadb-backup parameter --use-memory is equivalent to the innodb_buffer_pool_size of the server during recovery. In the implementation of log-based recovery, up to one third of that memory will be used for buffering log records, and the rest for copies of data pages.

Before 10.5, it was actually quite a bit more complicated than that. First of all, a single log record could be split into multiple parts if it was longer than RECV_DATA_BLOCK_SIZE. In the MDEV-12353 format, such splitting is not necessary, and MDEV-21351 simplified the memory management during recovery.

I am afraid that before 10.5, it is possible (but unlikely) that recovery may run out of memory even when using the same size of buffer pool that the server was using previously. Preparing a backup is similar to executing crash recovery. The reason for this is that the enforcement of the one-third rule is somewhat inaccurate and scattered in the code. Accurate implementation of the memory limit was possible in 10.5 thanks to the data structure simplification and the rewrite of the recovery logic.

Starting with 10.5, the expectation is that recovery will work even if the buffer pool size is significantly reduced, or when using an innodb_log_file_size that is several times innodb_buffer_pool_size. The latest fix MDEV-26784 was a glitch that might affect only extremely small buffer pools (something like 256×innodb_page_size or less).

The recommendation is to prepare backups with the same version of the backup tool that was used for creating a backup. Personally, I would recommend always preparing every backup, to ensure the validity of the backup. The preparation should best be run on a separate system, to avoid disturbing the database server with extra I/O and memory usage.

Due to the log file format change of MDEV-12353, mariadb-backup version 10.5 or later will refuse to prepare a backup that was created with an older version, just like the server will refuse to ‘crash-upgrade’ from an earlier version than 10.5.

Comment by Matthias Leich [ 2022-03-01 ] 

There were no serious mariabackup related tests for MariaDB version < 10.5 within the last months.
 
The dataset used for RQG tests invoking mariabackup is rather small.

Comment by Geoff Montee (Inactive) [ 2022-04-05 ]

Details and recommendations about memory usage while preparing a backup have been added to the following documentation pages:

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