[MDEV-13822] Mariabackup --prepare --incremental sets file size incorrectly Created: 2017-09-16  Updated: 2017-11-21  Resolved: 2017-10-10

Status: Closed
Project: MariaDB Server
Component/s: Backup
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.1.29, 10.2.10

Type: Bug Priority: Critical
Reporter: Marko Mäkelä Assignee: Vladislav Vaintroub
Resolution: Fixed Votes: 0
Labels: backup, corruption

Attachments: File apply-log-only-incr1.test    
Issue Links:
Problem/Incident
causes MDEV-14447 mariabackup --incremental --prepare f... Closed
Relates
relates to MDEV-9566 Add xtrabackup tool to MariaDB 10.1 Closed
relates to MDEV-11556 InnoDB redo log apply fails to adjust... Closed
relates to MDEV-13310 Preparing an incremental backup twice... Closed
relates to MDEV-13798 Error in MariaBackup incremental backup Closed
relates to MDEV-13807 mariabackup --apply-log-only does gen... Closed
relates to MDEV-13821 mariabackup does not display ib_logf(... Closed
Sprint: 10.2.10

 Description   

In Mariabackup --prepare --incremental, the file sizes are not being set correctly. Non-incremental restore (and InnoDB crash recovery) was fixed by me in MDEV-11556.
Percona Xtrabackup (as well as Oracle’s backup product) work around this problem by silently extending files when applying redo log records.

This has been witnessed once with the original test that was supplied to MDEV-13807.
The committed version of the test inserts fewer records and might not repeat this.

An excerpt from the buildbot log:

InnoDB: Starting final batch to recover 5 pages from redo log
 
 
 
xtrabackup: starting shutdown with innodb_fast_shutdown = 1
 
InnoDB: Starting shutdown...
 
InnoDB: Some resources were not cleaned up in shutdown: threads 0, events 18, os_mutexes 16, os_fast_mutexes 34
 
InnoDB: Shutdown completed; log sequence number 1632600
 
170915 23:51:29 completed OK!
 
D:/win32-debug/build/extra/mariabackup/Debug/mariabackup.exe based on MariaDB server 10.1.27-MariaDB Win32 (AMD64) 
incremental backup from 1629454 is enabled.
 
xtrabackup: cd to D:\win32-debug\build\mysql-test\var\2\tmp\backup\
 
xtrabackup: This target seems to be already prepared with --apply-log-only.
 
xtrabackup: xtrabackup_logfile detected: size=2097152, start_lsn=(9560649)
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = .\
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = D:\win32-debug\build\mysql-test\var\2\tmp\backup_inc1\
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2097152
 
…
 
InnoDB: Completed initialization of buffer pool
 
abort() has been called170915 23:51:31 [ERROR] mysqld got exception 0x80000003 ;
 
This could be because you hit a bug. It is also possible that this binary
 
…
 
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...
 
mariabackup.exe!my_sigabrt_handler()[my_thr_init.c:488]
 
mariabackup.exe!raise()[signal.cpp:516]
 
mariabackup.exe!abort()[abort.cpp:64]
 
mariabackup.exe!ib_logf()[ha_innodb.cc:21967]
 
mariabackup.exe!fil_report_invalid_page_access()[fil0fil.cc:6102]
 
mariabackup.exe!_fil_io()[fil0fil.cc:6335]
 
mariabackup.exe!buf_read_page_low()[buf0rea.cc:250]
 
mariabackup.exe!buf_read_recv_pages()[buf0rea.cc:1105]
 
mariabackup.exe!recv_read_in_area()[log0recv.cc:1857]
 
mariabackup.exe!recv_apply_hashed_log_recs()[log0recv.cc:1929]
 
mariabackup.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2661]
 
mariabackup.exe!innodb_init()[xtrabackup.cc:1735]
 
mariabackup.exe!xtrabackup_prepare_func()[xtrabackup.cc:5789]
 
mariabackup.exe!main()[xtrabackup.cc:6665]
 
mariabackup.exe!invoke_main()[exe_common.inl:64]
 
mariabackup.exe!__scrt_common_main_seh()[exe_common.inl:259]
 
mariabackup.exe!__scrt_common_main()[exe_common.inl:302]
 
mariabackup.exe!mainCRTStartup()[exe_main.cpp:17]
 
KERNEL32.DLL!BaseThreadInitThunk()
 
ntdll.dll!RtlInitializeExceptionChain()
 
ntdll.dll!RtlInitializeExceptionChain()
 
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.
 
mysqltest: At line 33: exec of 'D:/win32-debug/build/extra/mariabackup/Debug/mariabackup.exe --prepare --apply-log-only --target-dir=D:/win32-debug/build/mysql-test/var/2/tmp/backup --incremental-dir=D:/win32-debug/build/mysql-test/var/2/tmp/backup_inc1 ' failed, error: 255, status: 255, errno: 2
 
Output from before failure:
 
# expect NOT FOUND
 
 
 
 
 
 
 
The result from queries just before the failure was:
 
call mtr.add_suppression("InnoDB: New log files created");
 
CREATE TABLE t(a varchar(60)) ENGINE INNODB;
 
start transaction;
 
INSERT INTO t VALUES(1);
 
start transaction;
 
INSERT INTO t select uuid() from seq_1_to_100000;
 
NOT FOUND /Rollback of trx with id / in current_test 
# expect NOT FOUND

This reveals another problem (MDEV-13821) that is unique to Mariabackup 10.1: the messages from the ib_logf() call is lost. In Mariabackup 10.2, all ib::logger output is visible.
The problem is obvious from the message that fil_report_invalid_page_access() was trying to display.

Mariabackup 10.2 uses the same logic for restoring incremental backups. That bug is present in Mariabackup 10.2 as well.

 Comments   
Comment by Vladislav Vaintroub [ 2017-09-16 ]

Could you attach your test case please

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

Sorry, I forgot to mention the test case name. It is in the buildbot log: mariabackup.apply-log-only-incr

Comment by Andrii Nikitin (Inactive) [ 2017-09-20 ]

I can reliably see the crash by increasing incremental backup volume in apply-log-only-incr , see attached apply-log-only-incr1.test

a@UBINTI:~/env1$ m1-10.1/build/mysql-test/mtr  apply-log-only-incr1 --mem
 
Logging: /home/a/env1/_depot/m-branch/10.1/mysql-test/mysql-test-run.pl  apply-log-only-incr1 --mem
 
vardir: /home/a/env1/m1-10.1/build/mysql-test/var
 
Checking leftover processes...
 
Removing old var directory...
 
Creating var directory '/home/a/env1/m1-10.1/build/mysql-test/var'...
 
 - symlinking 'var' to '/dev/shm/var_auto_Xi2X'
 
Checking supported features...
 
MariaDB Version 10.1.27-MariaDB
 
 - SSL connections supported
 
Sphinx 'indexer' binary not found, sphinx suite will be skipped
 
Collecting tests...
 
Installing system database...
 
 
 
==============================================================================
 
 
 
TEST                                      RESULT   TIME (ms) or COMMENT
 
--------------------------------------------------------------------------
 
 
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
call mtr.add_suppression("InnoDB: New log files created");
 
CREATE TABLE t(a INT UNSIGNED PRIMARY KEY, b varchar(40)) ENGINE INNODB;
 
start transaction;
 
NOT FOUND /Rollback of trx with id/ in current_test
 
# expect NOT FOUND
 
mariabackup.apply-log-only-incr1 'innodb_plugin' [ fail ]
 
        Test ended at 2017-09-20 06:40:16
 
 
 
CURRENT_TEST: mariabackup.apply-log-only-incr1
 
/home/a/env1/m1-10.1/build/extra/mariabackup/mariabackup based on MariaDB server 10.1.27-MariaDB Linux (x86_64) 
incremental backup from 1629454 is enabled.
 
xtrabackup: cd to /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup/
 
xtrabackup: This target seems to be already prepared with --apply-log-only.
 
xtrabackup: xtrabackup_logfile detected: size=2818048, start_lsn=(87443196)
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1/
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2818048
 
xtrabackup: Generating a list of tablespaces
 
xtrabackup: page size for /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//ibdata1.delta is 16384 bytes
 
2017-09-20  6:40:15 140401058917312 [Warning] InnoDB: Failed to set O_DIRECT on file /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//ibdata1.delta: OPEN: Invalid argument, continuing anyway. O_DIRECT is known to result in 'Invalid argument' on Linux on tmpfs, see MySQL Bug#26662.
 
Applying /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//ibdata1.delta to ./ibdata1...
 
xtrabackup: page size for /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//test/t.ibd.delta is 16384 bytes
 
Applying /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//test/t.ibd.delta to ./test/t.ibd...
 
xtrabackup: page size for /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//mysql/innodb_index_stats.ibd.delta is 16384 bytes
 
Applying /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//mysql/innodb_index_stats.ibd.delta to ./mysql/innodb_index_stats.ibd...
 
xtrabackup: page size for /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//mysql/innodb_table_stats.ibd.delta is 16384 bytes
 
Applying /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1//mysql/innodb_table_stats.ibd.delta to ./mysql/innodb_table_stats.ibd...
 
xtrabackup: using the following InnoDB configuration for recovery:
 
xtrabackup:   innodb_data_home_dir = ./
 
xtrabackup:   innodb_data_file_path = ibdata1:12M:autoextend
 
xtrabackup:   innodb_log_group_home_dir = /home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1/
 
xtrabackup:   innodb_log_files_in_group = 1
 
xtrabackup:   innodb_log_file_size = 2818048
 
xtrabackup: Starting InnoDB instance for recovery.
 
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: The InnoDB memory heap is disabled
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Using SSE crc32 instructions
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Initializing buffer pool, size = 100.0M
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Completed initialization of buffer pool
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Starting crash recovery from checkpoint LSN=87443196
 
2017-09-20  6:40:15 140401058917312 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
 
2017-09-20  6:40:15 140401058917312 [ERROR] InnoDB: Trying to access page number 16 in space 0 space name ./ibdata1, which is outside the tablespace bounds. Byte offset 0, len 16384 i/o type 10.Please check that the configuration matches the InnoDB system tablespace location (ibdata files)
 
2017-09-20 06:40:15 7fb1ab3e2bc0  InnoDB: Assertion failure in thread 140401058917312 in file ha_innodb.cc line 21973
 
InnoDB: We intentionally generate a memory trap.
 
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
 
InnoDB: If you get repeated assertion failures or crashes, even
 
InnoDB: immediately after the mysqld startup, there may be
 
InnoDB: corruption in the InnoDB tablespace. Please refer to
 
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170920  6:40:15 [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.1.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 = 5311 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 0x48400
 
/home/a/env1/m1-10.1/build/extra/mariabackup/mariabackup(my_print_stacktrace+0x29)[0x55e7fb0b53b9]
 
/home/a/env1/m1-10.1/build/extra/mariabackup/mariabackup(handle_fatal_signal+0x3ad)[0x55e7facf60fd]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11670)[0x7fb1aafdb670]
 
mysys/stacktrace.c:268(my_print_stacktrace)[0x7fb1a946977f]
 
sql/signal_handler.cc:168(handle_fatal_signal)[0x7fb1a946b37a]
 
handler/ha_innodb.cc:21973(ib_logf(ib_log_level_t, char const*, ...))[0x55e7faf58f26]
 
fil/fil0fil.cc:6114(fil_report_invalid_page_access)[0x55e7faf146c8]
 
buf/buf0rea.cc:250(buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, unsigned long, unsigned long, long, unsigned long, trx_t*))[0x55e7faee4511]
 
buf/buf0rea.cc:512(buf_read_page(unsigned long, unsigned long, unsigned long, trx_t*))[0x55e7faee56c6]
 
buf/buf0buf.cc:3075(buf_page_get_gen(unsigned long, unsigned long, unsigned long, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, dberr_t*))[0x55e7faec95a5]
 
include/trx0undo.ic:174(trx_undo_page_get)[0x55e7fb040d47]
 
trx/trx0rseg.cc:214(trx_rseg_mem_create(unsigned long, unsigned long, unsigned long, unsigned long, ib_bh_t*, mtr_t*))[0x55e7fb034b3d]
 
trx/trx0rseg.cc:292(trx_rseg_create_instance)[0x55e7fb0353cc]
 
trx/trx0sys.cc:673(trx_sys_init_at_db_start())[0x55e7fb03695e]
 
srv/srv0start.cc:2654(innobase_start_or_create_for_mysql())[0x55e7fb020393]
 
mariabackup/xtrabackup.cc:1738(innodb_init())[0x55e7faa7c5d7]
 
mariabackup/xtrabackup.cc:5790(xtrabackup_prepare_func)[0x55e7faa67cf5]
 
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf1)[0x7fb1a94543f1]
 
/home/a/env1/m1-10.1/build/extra/mariabackup/mariabackup(_start+0x2a)[0x55e7faa7b07a]
 
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.
 
Aborted (core dumped)
 
mysqltest: At line 38: exec of '/home/a/env1/m1-10.1/build/extra/mariabackup/mariabackup --prepare --apply-log-only --target-dir=/home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup --incremental-dir=/home/a/env1/m1-10.1/build/mysql-test/var/tmp/backup_inc1 ' failed, error: 34304, status: 134, errno: 2
 
Output from before failure:
 
# expect NOT FOUND
 
 
 
 - saving '/home/a/env1/m1-10.1/build/mysql-test/var/log/mariabackup.apply-log-only-incr1-innodb_plugin/' to '/home/a/env1/m1-10.1/build/mysql-test/var/log/mariabackup.apply-log-only-incr1-innodb_plugin/'
 
--------------------------------------------------------------------------
 
The servers were restarted 0 times
 
Spent 0.000 of 53 seconds executing testcases
 
 
 
Failure: Failed 1/1 tests, 0.00% were successful.
 
 
 
Failing test(s): mariabackup.apply-log-only-incr1
 
 
 
The log files in var/log may give you some hint of what went wrong.
 
 
 
If you want to report this error, please read first the documentation
 
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
 
 
mysql-test-run: *** ERROR: there were failing test cases

Comment by Marko Mäkelä [ 2017-09-20 ]

I think that to fix this, the following should be done:

  1. If the .delta files ignore the all-zero tail of .ibd files, we can still determine the desired file size by looking at the FSP_SIZE field in page 0. Simply, when applying .delta file to page 0, also extend the file to the size indicated by FSP_SIZE. No change to the .delta file format is needed.
  2. Test also with --skip-innodb-changed-pages in 10.1, because in 10.2 that option does not exist yet.
  3. After applying each .delta file, delete that .delta file. This is just the safe and sane thing to do, and will fix MDEV-13310 in 10.2.
Generated at Thu Feb 08 08:08:38 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.