preparing a partial backup creates spurious "missing" .ibds

[Andrew Garner]

In xtrabackup 2.2.6, if I prepare a partial backup consisting of the the InnoDB shared tablespaces and .ibd files I wish to restore along the xtrabackup generated files, innobackupex --apply-log recreates a subset of the missing .ibds presumably based on the contents of the xtrabackup_logfile obtained during the backup.

Previous versions of xtrabackup seemed to have more expected behavior where it warned about missing tablespaces, and otherwise silently dropped them from the data dictionary without attempting to create the missing .ibd files.

Before innobackup --apply-log:

# ls -1 ./staging/
backup-my.cnf
ibdata1
mydb/
xtrabackup_binlog_info
xtrabackup_checkpoints
xtrabackup_info
xtrabackup_logfile

After innobackupex --apply-log
# ls -1 ./staging/
backup-my.cnf
ibdata1
mydb/
db00/
db01/
db02/
...
xtrabackup_binlog_info
xtrabackup_checkpoints
xtrabackup_info
xtrabackup_logfile

Where these dbXX databases are populated with .ibd files only, created during the apply-log phase.

[Nilnandan Joshi (nilnandan-joshi)]

I could not reproduce this with PS 5.6.21 and Xtrabackup 2.2.6. Can you able to provide exact steps for taking backup and apply-log?

Taking backup for only "nil" DB.

nilnandan@Dell-XPS:~$ sudo innobackupex --user=root --password=root --databases="nil" /home/nilnandan/backup
[sudo] password for nilnandan:

...
innobackupex: Using server version 5.6.21-70.1

innobackupex: Created backup directory /home/nilnandan/backup/2014-12-09_10-22-24

141209 10:22:24 innobackupex: Starting ibbackup with command: xtrabackup --defaults-group="mysqld" --backup --suspend-at-end --target-dir=/home/nilnandan/backup/2014-12-09_10-22-24 --innodb_log_file_size="50331648" --innodb_data_file_path="ibdata1:12M:autoextend" --tmpdir=/tmp --extra-lsndir='/tmp' --databases='nil'
innobackupex: Waiting for ibbackup (pid=5653) to suspend
innobackupex: Suspend file '/home/nilnandan/backup/2014-12-09_10-22-24/xtrabackup_suspended_2'

xtrabackup version 2.2.6 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
xtrabackup: uses posix_fadvise().
xtrabackup: cd to /var/lib/mysql
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
>> log scanned up to (38314921)
xtrabackup: Generating a list of tablespaces
[01] Copying ./ibdata1 to /home/nilnandan/backup/2014-12-09_10-22-24/ibdata1
[01] ...done
>> log scanned up to (38314921)
xtrabackup: Creating suspend file '/home/nilnandan/backup/2014-12-09_10-22-24/xtrabackup_suspended_2' with pid '5654'

141209 10:22:26 innobackupex: Continuing after ibbackup has suspended
141209 10:22:26 innobackupex: Executing LOCK TABLES FOR BACKUP...
141209 10:22:26 innobackupex: Backup tables lock acquired

141209 10:22:26 innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/var/lib/mysql/'
innobackupex: Backing up file '/var/lib/mysql//nil/db.opt'
innobackupex: Backing up file '/var/lib/mysql//nil/test.frm'
141209 10:22:26 innobackupex: Finished backing up non-InnoDB tables and files

141209 10:22:26 innobackupex: Executing LOCK BINLOG FOR BACKUP...
>> log scanned up to (38314921)
141209 10:22:26 innobackupex: Executing FLUSH ENGINE LOGS...
141209 10:22:26 innobackupex: Waiting for log copying to finish

xtrabackup: The latest check point (for incremental): '38314921'
xtrabackup: Stopping log copying thread.
.>> log scanned up to (38314921)

xtrabackup: Creating suspend file '/home/nilnandan/backup/2014-12-09_10-22-24/xtrabackup_log_copied' with pid '5654'
xtrabackup: Transaction log of lsn (38314921) to (38314921) was copied.
141209 10:22:27 innobackupex: Executing UNLOCK BINLOG
141209 10:22:27 innobackupex: Executing UNLOCK TABLES
141209 10:22:27 innobackupex: All tables unlocked

innobackupex: Backup created in directory '/home/nilnandan/backup/2014-12-09_10-22-24'
141209 10:22:27 innobackupex: Connection to database server closed
141209 10:22:27 innobackupex: completed OK!
nilnandan@Del...

[Andrew Garner (muzazzi)]

I did not mean to imply that every database (or .ibd) is recreated. This seems to occur only with .ibds that are modified during the backup phase. In your test case, I can see from the LSNs that nothing is being written during the backup so you would not expect to see this behavior manifest.

I will try to attach a reproducible test case. This would involve writing to some tables that will not be extracted from the backup, and as apply-logs processes records for those tables we would see .ibds being created.

[Nilnandan Joshi (nilnandan-joshi)]

I have again tried to run sysbench on the particular database for running transactions and meanwhile try to take backup of that DB and check but unable to reproduce the issue. I have also tried to run sysbench on one db and take backup of other db but still the result is same. I think, its better if you can provide the test case.

nilnandan@Dell-XPS:~$ sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --oltp-table-size=100000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=100 --max-time=120 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-password=root run
sysbench 0.5: multi-threaded system evaluation benchmark

Running the test with following options:
Number of threads: 100
Random number generator seed is 0 and will be ignored

Threads started!

OLTP test statistics:
    queries performed:
        read: 2160928
        write: 617394
        other: 308698
        total: 3087020
    transactions: 154346 (1285.64 per sec.)
    read/write requests: 2778322 (23142.30 per sec.)
    other operations: 308698 (2571.33 per sec.)
    ignored errors: 6 (0.05 per sec.)
    reconnects: 0 (0.00 per sec.)

General statistics:
    total time: 120.0539s
    total number of events: 154346
    total time taken by event execution: 12002.7282s
    response time:
         min: 7.87ms
         avg: 77.77ms
         max: 458.67ms
         approx. 95 percentile: 143.40ms

Threads fairness:
    events (avg/stddev): 1543.4600/60.97
    execution time (avg/stddev): 120.0273/0.01

nilnandan@Dell-XPS:~$

nilnandan@Dell-XPS:~/Downloads/percona-xtrabackup-2.2.6-Linux-x86_64/bin$ sudo ./innobackupex --user=root --password=root --databases="dbtest" /home/nilnandan/backup

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.

Get the latest version of Percona XtraBackup, documentation, and help resources:
http://www.percona.com/xb/p

141229 13:58:42 innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_group=xtrabackup' as 'root' (using password: YES).
141229 13:58:42 innobackupex: Connected to MySQL server
141229 13:58:42 innobackupex: Executing a version check against the server...
141229 13:58:42 innobackupex: Done.
141229 13:58:42 innobackupex: Starting the backup operation

IMPORTANT: Please check that the backup run completes successfully.
           At the end of a successful backup run innobackupex
           prints "completed OK!".

innobackupex: Using server version 5.6.21-70.1

innobackupex: Created backup directory /home/nilnandan/backup/2014-12-29_13-58-42

141229 13:58:42 innobackupex: Starting ibbackup with command: xtrabackup --defaults-group...

[Andrew Garner (muzazzi)]

I was able to create a simple reproducible set of steps to recreate this issue. This seems to be DDL related rather than DML related - I can't reproduce this with any normal DML workload.

I created a small sandbox - for the test case using MySQL 5.6.22 from a binary tarball acquired from the mysql.com cdn.

I created two databases:

mysql[sandbox]> SELECT @@version, @@version_comment;
+------------+------------------------------+
| @@version | @@version_comment |
+------------+------------------------------+
| 5.6.22-log | MySQL Community Server (GPL) |
+------------+------------------------------+
1 row in set (0.00 sec)

mysql[sandbox]> create database include00;
Query OK, 1 row affected (0.00 sec)

mysql[sandbox]> create database exclude00;
Query OK, 1 row affected (0.00 sec)

I created a simple table structure in the include00 database:

mysql[sandbox]> use include00
Database changed
mysql[sandbox]> create table table00 (id bigint unsigned primary key auto_increment, data varchar(40)) engine=innodb character set = utf8;
Query OK, 0 rows affected (0.03 sec)

I populated this with data until the table was a few hundred MB in size - large enough that the copy would pause momentarily while copying this table so I could ensure the DDL operation on a table in an excluded database completes before the backup ends.

I create an empty table in the exclude00 database.

mysql[sandbox]> create table excluded_table00 (id int) engine=innodb;
Query OK, 0 rows affected (0.03 sec)

I start xtrabackup:

# innobackupex --defaults-file=$PWD/my.sandbox.cnf --databases=include00 /backups/

After xtrabackup starts copying tablespace I issue a DDL command:

mysql[sandbox]> truncate table excluded_table00;
Query OK, 0 rows affected (0.03 sec)

Xtrabackup finishes and I see:

xtrabackup: Transaction log of lsn (1025116390) to (1025124616) was copied.
innobackupex: Backup created in directory '/backups/2014-12-29_18-43-43'

The contents of /backups/2014-12-29_18-43-43 are as expected (prior to prepare):

# tree -a /backups/2014-12-29_18-43-43
/backups/2014-12-29_18-43-43
├── backup-my.cnf
├── ibdata1
├── include00
│   ├── db.opt
│   ├── table00.frm
│   └── table00.ibd
├── xtrabackup_checkpoints
├── xtrabackup_info
└── xtrabackup_logfile

I prepare the backup:

# innobackupex --apply-log /backups/2014-12-29_18-43-43
...
141229 18:46:00 innobackupex: completed OK!

And the post-prepare contents are:

# tree -a /backups/2014-12-29_18-43-43
/backups/2014-12-29_18-43-43
├── backup-my.cnf
├── exclude00
│   └── excluded_table00.ibd
├── ibdata1
├── ib_logfile0
├── ib_logfile1
├── include00
│   ├── db.opt
│   ├── table00.frm
│   └── table00.ibd
├── xtrabackup_checkpoints
├── xtrabackup_info
└── xtrabackup_logfile

2 directories, 11 files

The exclude00/excluded_table00.ibd has appeared which is not expected. I have attached the innobackupex --apply-log output.

[Nilnandan Joshi (nilnandan-joshi)]

Hi, Thanks for test case. I was able to reproduce the same with PS 5.6.21 and Xtrabackup 2.2.7

root@desktop:~# xtrabackup --version
xtrabackup version 2.2.7 based on MySQL server 5.6.21 Linux (x86_64) (revision id: )
root@desktop:~#

nilnandan@desktop:~$ mysql -uroot -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 47
Server version: 5.6.21-70.1 Percona Server (GPL), Release 70.1, Revision 698

...
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql>
mysql> SELECT @@version, @@version_comment;
+-------------+--------------------------------------------------+
| @@version | @@version_comment |
+-------------+--------------------------------------------------+
| 5.6.21-70.1 | Percona Server (GPL), Release 70.1, Revision 698 |
+-------------+--------------------------------------------------+
1 row in set (0.00 sec)

mysql> create database include00;
Query OK, 1 row affected (0.00 sec)

mysql> create database exclude00;
Query OK, 1 row affected (0.00 sec)

mysql> use include00
Database changed
mysql>
mysql> create table table00 (id bigint unsigned primary key auto_increment, data varchar(40)) engine=innodb character set = utf8;
Query OK, 0 rows affected (0.01 sec)

mysql> insert into table00 (data) values ('abcdnedlkjsdlkjasdlkj alkjdlaskjldkjasdl');
Query OK, 1 row affected, 0 warning (0.00 sec)

mysql> select * from table00;
+----+------------------------------------------+
| id | data |
+----+------------------------------------------+
| 1 | abcdnedlkjsdlkjasdlkj alkjdlaskjldkjasdl |
+----+------------------------------------------+
1 row in set (0.00 sec)

mysql> insert into table00 (data) select data from table00;
Query OK, 1 row affected (0.01 sec)
Records: 1 Duplicates: 0 Warnings: 0

...
mysql> insert into table00 (data) select data from table00;
Query OK, 8388608 rows affected (33.35 sec)
Records: 8388608 Duplicates: 0 Warnings: 0

----- Take a backup with this.

root@desktop:~# innobackupex --user=root --password=root --databases='include00' /home/nilnandan/backup

InnoDB Backup Utility v1.5.1-xtrabackup; Copyright 2003, 2009 Innobase Oy
and Percona LLC and/or its affiliates 2009-2013. All Rights Reserved.

This software is published under
the GNU GENERAL PUBLIC LICENSE Version 2, June 1991.
....

Simultaneously, ran truncate
mysql> truncate table excluded_table00;
Query OK, 0 rows affected (0.34 sec)

Before --apply-log

root@desktop:~# tree -a /home/nilnandan/backup/2014-12-30_11-57-31/
/home/nilnandan/backup/2014-12-30_11-57-31/
├── backup-my.cnf
├── ibdata1
├── include00
│   ├── db.opt
│   ├── table00.frm
│   └── table00.ibd
├── xtrabackup_checkpoints
├── xtrabackup_info
└── xtrabackup_logfile

1 directory, 8 files
root@desktop:~#

-- After --apply-log

root@desktop:~# tree -a /home/nilnandan/backup/2014-12-30_11-57-31/
/home/nilnandan/backup/2014-12-30_11-57-31/
├── backup-my.cnf
├── exclude00
│   └── excluded_table00.ibd
├── ibdata1
├── ib_logfile0
├── ib_logfile1
├── include00
│   ├── db.opt
│   ├── table00.frm
│   └── table00.ibd
├── xtrabackup_checkpoints...

[Alexey Kopytov (akopytov)]

TRUNCATE is equivalent to DROP + CREATE. Which means to fix this bug we should filter tablespace creation operations when preparing a partial backup based on the original pattern which was used to create the partial backup.

A related problem is when during a partial backup a regular CREATE TABLE is executed for a InnoDB table which does not match the filters. It would still be present in the resulting backup after prepare, but that's not what users would expect.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PXB-714