xtrabackup 2.4.7 crashes while backing up MariaDB 10.2.x with ftwrl-* options

Bug #1704636 reported by Valerii Kravchuk on 2017-07-16
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona XtraBackup
Status tracked in 2.4
2.3
Medium
Sergei Glushchenko
2.4
Medium
Sergei Glushchenko

Bug Description

The following simple test performed on idle (no connections) almost "empty" instance of MariaDB 10.2.7 started with all defaults but port and datadir shows the problem:

openxs@ao756:~$ /usr/bin/xtrabackup --no-defaults --host=127.0.0.1 --port=3308 --datadir=/home/openxs/dbs/maria10.2/data --user=root --backup --compress --ftwrl-wait-timeout=5 --ftwrl-wait-threshold=300 --ftwrl-wait-query-type=all --target-dir=/home/openxs/backup
170716 13:16:52 version_check Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup;host=127.0.0.1;port=3308' as 'root' (using password: NO).
170716 13:16:52 version_check Connected to MySQL server
170716 13:16:52 version_check Executing a version check against the server...
170716 13:16:52 version_check Done.
170716 13:16:52 Connecting to MySQL server host: 127.0.0.1, user: root, password: not set, port: 3308, socket: not set
Using server version 10.2.7-MariaDB-log
/usr/bin/xtrabackup version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 05f1fcf)
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /home/openxs/dbs/maria10.2/data
xtrabackup: open files limit requested 0, set to 1024
xtrabackup: using the following InnoDB configuration:
xtrabackup: innodb_data_home_dir = .
xtrabackup: innodb_data_file_path = ibdata1:12M:autoextend
xtrabackup: innodb_log_group_home_dir = ./
xtrabackup: innodb_log_files_in_group = 2
xtrabackup: innodb_log_file_size = 50331648
InnoDB: Number of pools: 1
170716 13:16:52 >> log scanned up to (298878845)
xtrabackup: Generating a list of tablespaces
InnoDB: Allocated tablespace ID 1 for mysql/innodb_table_stats, old maximum was 0
170716 13:16:52 [01] Compressing ./ibdata1 to /home/openxs/backup/ibdata1.qp
170716 13:16:52 [01] ...done
170716 13:16:52 [01] Compressing ./mysql/innodb_table_stats.ibd to /home/openxs/backup/mysql/innodb_table_stats.ibd.qp
170716 13:16:52 [01] ...done
170716 13:16:53 [01] Compressing ./mysql/innodb_index_stats.ibd to /home/openxs/backup/mysql/innodb_index_stats.ibd.qp
170716 13:16:53 [01] ...done
170716 13:16:53 [01] Compressing ./mysql/gtid_slave_pos.ibd to /home/openxs/backup/mysql/gtid_slave_pos.ibd.qp
170716 13:16:53 [01] ...done
170716 13:16:53 [01] Compressing ./test/sbtest1.ibd to /home/openxs/backup/test/sbtest1.ibd.qp
170716 13:16:53 >> log scanned up to (298878845)
170716 13:16:54 >> log scanned up to (298878845)
170716 13:16:55 >> log scanned up to (298878845)
170716 13:16:56 >> log scanned up to (298878845)
170716 13:16:57 >> log scanned up to (298878845)
170716 13:16:58 >> log scanned up to (298878845)
170716 13:16:59 >> log scanned up to (298878845)
170716 13:17:00 >> log scanned up to (298878845)
170716 13:17:00 [01] ...done
170716 13:17:00 [01] Compressing ./test/tt1.ibd to /home/openxs/backup/test/tt1.ibd.qp
170716 13:17:00 [01] ...done
170716 13:17:00 [01] Compressing ./test/task.ibd to /home/openxs/backup/test/task.ibd.qp
170716 13:17:00 [01] ...done
170716 13:17:00 [01] Compressing ./test/incident.ibd to /home/openxs/backup/test/incident.ibd.qp
170716 13:17:00 [01] ...done
170716 13:17:00 [01] Compressing ./test/tt2.ibd to /home/openxs/backup/test/tt2.ibd.qp
170716 13:17:00 [01] ...done
170716 13:17:01 [01] Compressing ./test/t1i.ibd to /home/openxs/backup/test/t1i.ibd.qp
170716 13:17:01 [01] ...done
170716 13:17:01 [01] Compressing ./test/t.ibd to /home/openxs/backup/test/t.ibd.qp
170716 13:17:01 [01] ...done
170716 13:17:01 [01] Compressing ./test/bd.ibd to /home/openxs/backup/test/bd.ibd.qp
170716 13:17:01 [01] ...done
170716 13:17:01 [01] Compressing ./test/tt.ibd to /home/openxs/backup/test/tt.ibd.qp
170716 13:17:01 [01] ...done
170716 13:17:01 >> log scanned up to (298878845)
170716 13:17:01 Waiting 5 seconds for queries running longer than 300 seconds to finish
10:17:01 UTC - xtrabackup got signal 11 ;
This could be because you hit a bug or data is corrupted.
This error can also be caused by malfunctioning hardware.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

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 = 0 thread_stack 0x10000
/usr/bin/xtrabackup(my_print_stacktrace+0x2c)[0xec559c]
/usr/bin/xtrabackup(handle_fatal_signal+0x262)[0xa425f2]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10330)[0x7f1fab2be330]
/lib/x86_64-linux-gnu/libc.so.6(+0x3d467)[0x7f1fa91e2467]
/usr/bin/xtrabackup(_Z11lock_tablesP8st_mysql+0x114)[0x738304]
/usr/bin/xtrabackup(_Z12backup_startv+0x80)[0x73fdc0]
/usr/bin/xtrabackup(_Z22xtrabackup_backup_funcv+0x140d)[0x722ead]
/usr/bin/xtrabackup(main+0xd2a)[0x70035a]
/lib/x86_64-linux-gnu/libc.so.6(__libc_start_main+0xf5)[0x7f1fa91c6f45]
/usr/bin/xtrabackup[0x717ef4]

Please report a bug at https://bugs.launchpad.net/percona-xtrabackup
openxs@ao756:~$

The problem is repeatable with 10.2.6, but is not repeatable with Percona Server 5.7.x or MariaDB 10.1.x.

Without these options everything works as expected:

openxs@ao756:~$ /usr/bin/xtrabackup --no-defaults --host=127.0.0.1 --port=3308 --datadir=/home/openxs/dbs/maria10.2/data --user=root --backup --compress --target-dir=/home/openxs/backup
...
170716 13:21:50 [01] Compressing ./test/sbtest1.frm to /home/openxs/backup/test/sbtest1.frm.qp
170716 13:21:50 [01] ...done
170716 13:21:50 [01] Compressing ./test/db.opt to /home/openxs/backup/test/db.opt.qp
170716 13:21:50 [01] ...done
170716 13:21:50 [01] Compressing ./test/t1i.frm to /home/openxs/backup/test/t1i.frm.qp
170716 13:21:50 [01] ...done
170716 13:21:50 [01] Compressing ./performance_schema/db.opt to /home/openxs/backup/performance_schema/db.opt.qp
170716 13:21:50 [01] ...done
170716 13:21:50 Finished backing up non-InnoDB tables and files
170716 13:21:50 [00] Compressing xtrabackup_binlog_info
170716 13:21:50 [00] ...done
170716 13:21:50 Executing FLUSH NO_WRITE_TO_BINLOG ENGINE LOGS...
xtrabackup: The latest check point (for incremental): '298878836'
170716 13:21:50 >> log scanned up to (298878845)
xtrabackup: Stopping log copying thread.

170716 13:21:50 Executing UNLOCK TABLES
170716 13:21:50 All tables unlocked
170716 13:21:50 [00] Compressing ib_buffer_pool to /home/openxs/backup/ib_buffer_pool.qp
170716 13:21:50 [00] ...done
170716 13:21:50 Backup created in directory '/home/openxs/backup/'
MySQL binlog position: filename 'ao756-bin.000001', position '328', GTID of the last change ''
170716 13:21:50 [00] Compressing backup-my.cnf
170716 13:21:50 [00] ...done
170716 13:21:50 [00] Compressing xtrabackup_info
170716 13:21:50 [00] ...done
xtrabackup: Transaction log of lsn (298878836) to (298878845) was copied.
170716 13:21:50 completed OK!

Well, it is kind of incompatibility introduced by MariaDB. Have you ever seen SHOW PROCESSLIST returning NULL in TIME column? MariaDB does so.

MariaDB [(none)]> show processlist;
+----+-------------+-----------+------+---------+------+--------------------------+------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+----+-------------+-----------+------+---------+------+--------------------------+------------------+----------+
| 1 | system user | | NULL | Daemon | NULL | InnoDB purge coordinator | NULL | 0.000 |
| 2 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 3 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 4 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 5 | system user | | NULL | Daemon | NULL | InnoDB shutdown handler | NULL | 0.000 |
| 19 | root | localhost | NULL | Sleep | 156 | | NULL | 0.000 |
| 20 | root | localhost | NULL | Query | 0 | init | show processlist | 0.000 |
+----+-------------+-----------+------+---------+------+--------------------------+------------------+----------+
7 rows in set (0.00 sec)

It is trivial to fix. But I wonder who would use these options having that MariaDB has support for backup locks?

tags: added: mariadb
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers