Rainsbrook

This page is read only. You can view the source, but not change it. Ask your administrator if you think this is wrong.
====== Percona MySQL ======


===== MySQL version =====


Server version: 5.5.34-32.0-log Percona Server (GPL), Release 32.0


Storage engine is InnoDB.



to re-download the exact version that we are using on the Production database servers:
https://www.percona.com/downloads/Percona-Server-5.5/Percona-Server-5.5.47-37.7/binary/debian/trusty



===== Backup commands from db on Linode =====

Included for reference only

  dbadmin@db:~/dump$ history | grep backup
   35  innobackupex --user=bkpuser --password=bkpuser --stream=tar |gzip -c -1 > /mnt/backup/backup/backup.`date +%Y-%m-%d-%H-%M-%S`.tar.gz
   36  cd /mnt/backup/backup/
   37  innobackupex --user=bkpuser --password=bkpuser --stream=tar ./ | gzip -c -1 > /mnt/backup/backup/backup.`date +%Y-%m-%d-%H-%M-%S`.tar.gz
   52  mkdir backup
   61  innobackupex --user=bkpuser --password=bkpuser /mnt/backup/backup/


===== Percona references =====

Create Backup:-

http://www.percona.com/doc/percona-xtrabackup/2.1/innobackupex/preparing_a_backup_ibk.html

Restore Backup:-

http://www.percona.com/doc/percona-xtrabackup/2.1/innobackupex/restoring_a_backup_ibk.html



===== Restore data to node B =====

Ensure mysqld is stopped.

  root@m1b:/mnt/datastore/db-backup# rm -rf /mnt/datastore/mysql/* 
  root@6m1b:/mnt/datastore/db-backup# innobackupex --copy-back 2014-05-19_09-10-01/
  
  innobackupex: Starting to copy files in '/mnt/datastore/db-backup/2014-05-19_09-10-01'
  innobackupex: back to original data directory '/mnt/datastore/mysql/'
  innobackupex: Copying '/mnt/datastore/db-backup/2014-05-19_09-10-01/xtrabackup_binlog_pos_innodb' to '/mnt/datastore/mysql/xtrabackup_binlog_pos_innodb'
  innobackupex: Creating directory '/mnt/datastore/mysql/cch6'
  innobackupex: Copying '/mnt/datastore/db-backup/2014-05-19_09-10-01/cch6/ident_progress.frm' to '/mnt/datastore/mysql/cch6/ident_progress.frm'
  innobackupex: Copying '/mnt/datastore/db-backup/2014-05-19_09-10-01/cch6/log_api.ibd' to '/mnt/datastore/mysql/cch6/log_api.ibd'
  .... edited ....
  innobackupex: Copying '/mnt/datastore/db-backup/2014-05-19_09-10-01/performance_schema/file_summary_by_event_name.frm' to '/mnt/datastore/mysql/performance_schema/file_summary_by_event_name.frm'
  innobackupex: Creating directory '/mnt/datastore/mysql/binlog'
  
  innobackupex: Starting to copy InnoDB system tablespace
  innobackupex: in '/mnt/datastore/db-backup/2014-05-19_09-10-01'
  innobackupex: back to original InnoDB data directory '/mnt/datastore/mysql/'
  innobackupex: Copying '/mnt/datastore/db-backup/2014-05-19_09-10-01/ibdata1' to '/mnt/datastore/mysql/ibdata1'
  
  innobackupex: Starting to copy InnoDB undo tablespaces
  innobackupex: in '/mnt/datastore/db-backup/2014-05-19_09-10-01'
  innobackupex: back to '/mnt/datastore/mysql/'
  
  innobackupex: Starting to copy InnoDB log files
  innobackupex: in '/mnt/datastore/db-backup/2014-05-19_09-10-01'
  innobackupex: back to original InnoDB log directory '/mnt/datastore/mysql/'
  innobackupex: Finished copying back files.
  
  140519 13:54:35  innobackupex: completed OK!
  root@db-s6m1b:/mnt/datastore/db-backup# 
  

You will need to chown files in ''mysql'' directory to mysql:mysql before starting the server.


===== Replication =====

See http://www.percona.com/doc/percona-xtrabackup/2.1/howtos/setting_up_replication.html


==== MASTER config ====
 
On Master, create slave user and permissions:-

<code mysql>
mysql> GRANT REPLICATION SLAVE ON *.* TO '6m1b'@'10.xx.yy.zz' IDENTIFIED BY 'm1b';
Query OK, 0 rows affected (0.43 sec)

mysql> FLUSH PRIVILEGES;
Query OK, 0 rows affected (0.17 sec)

mysql>
mysql> SHOW MASTER STATUS;
+------------------+----------+-----------------------------------------------+------------------+
| File             | Position | Binlog_Do_DB                                  | Binlog_Ignore_DB |
+------------------+----------+-----------------------------------------------+------------------+
| mysql-bin.000289 |      107 | binlog, cch6, expose6, fp6, monitoring6, pvp6 |                  |
+------------------+----------+-----------------------------------------------+------------------+
1 row in set (0.01 sec)

mysql>
</code>


Edit my.cnf to let mysql know about the binlogs to create:- 

<code>
# BINARY LOGGING #
log-bin                        = /mnt/datastore/mysql/binlog/mysql-bin
expire-logs-days               = 4
sync_binlog                    = 1

binlog_format                   = mixed

#see https://www.digitalocean.com/community/articles/how-to-set-up-master-slave-replication-in-mysql for sql commands needed
# See also http://www.percona.com/doc/percona-xtrabackup/2.1/howtos/setting_up_replication.html
</code>

The important thing to note is that database names can include spaces and commas so the ''binlog_do_db'' entries cannot be a comma/space separated list. The replication mode must be set to ''mixed'' to allow for both row and statement based replication.


The ''expire_logs_days'' above can be set as a global variable, so if it is known that logs are needed for longer (whilst, say a new replica is being started in a remote location with a long copy time), the validity time can be increased:-

<code mysql>
mysql> SHOW VARIABLES WHERE Variable_Name='expire_logs_days';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| expire_logs_days | 4     |
+------------------+-------+
1 row in set (0.00 sec)

mysql> set global expire_logs_days=6;
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW VARIABLES WHERE Variable_Name='expire_logs_days';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| expire_logs_days | 6     |
+------------------+-------+
1 row in set (0.00 sec)

mysql> 
</code>




==== SLAVE Config ====

Edit my.cnf to configure the replication filters:

<code base>
replicate-wild-do-table=bing_api.%
replicate-wild-do-table=cch6.%
replicate-wild-do-table=expose6.%
replicate-wild-do-table=fp6.%
replicate-wild-do-table=monitoring6.%
replicate-wild-do-table=pvp6_old.%
replicate-wild-do-table=wm6.%

replicate-wild-ignore-table=expose6.exptmp_%
replicate-wild-ignore-table=monitoring6.montmp_%
replicate-wild-ignore-table=fp6.cidtmp_%
</code>

<code bash>
root@m1b:/mnt/datastore/mysql# cat xtrabackup_binlog_info
mysql-bin.000289        107
root@m1b:/mnt/datastore/mysql# 
root@m1b:/mnt/datastore/mysql# mysql -u dbadmin -p
</code>
<code mysql>
mysql> CHANGE MASTER TO MASTER_HOST='10.xx.yyy.zz', MASTER_USER='m1b', MASTER_PASSWORD='m1b', MASTER_LOG_FILE='mysql-bin.000289', MASTER_LOG_POS=107;
Query OK, 0 rows affected (0.01 sec)

mysql> START SLAVE;
Query OK, 0 rows affected (0.00 sec)

mysql> 
</code>


From system error log:-
<code>
140715 10:06:10 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='10.100.200.11', master_port='3306', master_log_file='mysql-bin.000289', master_log_pos='107'.
140715 10:07:07 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000289' at position 107, relay log '/mnt/datastore/mysql/relay-bin.000001' position: 4
140715 10:07:07 [Note] Slave I/O thread: connected to master 'db-s6m1b@10.100.200.11:3306',replication started in log 'mysql-bin.000289' at position 107
</code>


==== Replication Mode ====


Currently set to:-

<code mysql>
mysql> show variables like "binlog_format";
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| binlog_format | MIXED |
+---------------+-------+
1 row in set (0.00 sec)

mysql> 
</code>


==== Find last binlog entry ====

This is the last point in binlog being written to, it is NOT the position to use for starting replication.

<code>
mysql> show master status;
+------------------+-----------+------------------------------------------+------------------+
| File             | Position  | Binlog_Do_DB                             | Binlog_Ignore_DB |
+------------------+-----------+------------------------------------------+------------------+
| mysql-bin.000292 | 398084789 | binlog,cch6,expose6,fp6,monitoring6,pvp6 |                  |
+------------------+-----------+------------------------------------------+------------------+
1 row in set (0.00 sec)

mysql> 
</code>


==== Set start point for replication on Slave ====

Assuming that Xtrabackup is being used to transfer data to the slave from the master, this will find the corrent position in binlog to start replication from.

<code>
root@m1b:/mnt/datastore/mysql# cat xtrabackup_binlog_info
mysql-bin.000296        415038146
root@m1b:/mnt/datastore/mysql#
</code>

<code>
mysql> CHANGE MASTER TO MASTER_HOST='10.xx.yy.zz', MASTER_USER='m1b', MASTER_PASSWORD='m1b', MASTER_LOG_FILE='mysql-bin.000296', MASTER_LOG_POS=415038146;
</code>


May be ''xtrabackup_binlog_pos_innodb''
<code>
root@db01b:/mnt/datastore/mysql# cat xtrabackup_binlog_pos_innodb
/data/mysql/binlog/mysql-bin.000999     203005933
root@db01b:/mnt/datastore/mysql#
</code>





==== Connecting from Amazon EC2 instance to the production database for replication ====


During a period of intermittent problems with the DC - Amazon VPC connectivity, we setup the Amazon db01d.aws.int.company to connect to the master database server using a temporary approach to work around the issue.

From the Amazon D server:
  * replication status to check current settings
  * show slave status \G
  * stop slave;
  * show slave status \G
  * assign an external IP to the Amazon com6-prod-db01d.aws.fmts.int instance

from the jk server:
  * tunnel the production database server through the ssh connection to the Amazon Instance.

<code>
dbadmin@infra-jenkins-rel01:~$ ssh root@52.aa.bb.cc -R 8888:10.xx.yy.zz:3306 -N
</code>

To enable this open /etc/ssh/sshd_config and add the following line somewhere in that config file.
<code>
GatewayPorts yes
</code>

From the Amazon D server:
  * ''CHANGE MASTER TO MASTER_HOST='127.0.0.1', master_port=8888, MASTER_USER='prod-db01d', MASTER_PASSWORD='prod-db01d', MASTER_LOG_FILE='mysql-bin.000379', MASTER_LOG_POS=624866777;''
  * show slave status \G
  * start slave;
  * show slave status \G

==== Set start point for replication on Slave ====

Assuming that Xtrabackup is being used to transfer data to the slave from the master, this will find the current position in binlog to start replication from.

<code>

root@prod-db01d:/data/mysql# more xtrabackup_slave_info
CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000370', MASTER_LOG_POS=326784188


</code>


Change below values as required, matching MASTER_LOG_FILE and MASTER_LOG_POS from previous statement.
<code>
mysql> CHANGE MASTER TO MASTER_HOST='10.xx.yy.zz', MASTER_USER='6m1X', MASTER_PASSWORD='6m1X', MASTER_LOG_FILE='mysql-bin.000370', MASTER_LOG_POS=326784188;


</code>







==== Testing replication ====

<code mysql>
mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.xx.yy.zz
                  Master_User: m1b
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000292
          Read_Master_Log_Pos: 545638836
               Relay_Log_File: relay-bin.000003
                Relay_Log_Pos: 108348516
        Relay_Master_Log_File: mysql-bin.000292
...edited...
               Master_SSL_Key: 
        Seconds_Behind_Master: 0

</code>

The values in the above text will change each time the command is run, this should indicate that both the replication threads are running OK. Clues to watch for are ''Read_Master_Log_Pos'' and ''Relay_Log_Pos'' both incrementing and ''Seconds_Behind_Master'' should be zero or close to zero. If ''Seconds_Behind_Master'' is increasing consistently, this may show a replication lag developing and this needs investigation.

Also, use a select statement on the slave, look for the last entries in a table, if replication is running, the id or primary key will be incrementing.

<code>
mysql> select id, asset_id, print_print_id, server_id, status from fp6.ingest order by id desc  limit 3;
+----------+----------+----------------+-----------+--------+
| id       | asset_id | print_print_id | server_id | status |
+----------+----------+----------------+-----------+--------+
| 15158360 |    26393 |       12063023 |         7 |      1 |
| 15158359 |    26393 |       12063023 |         5 |      1 |
| 15158358 |    26389 |       12063022 |         7 |      1 |
+----------+----------+----------------+-----------+--------+
3 rows in set (0.01 sec)

mysql>
mysql> select id, asset_id, print_print_id, server_id, status from fp6.ingest order by id desc  limit 3;
+----------+----------+----------------+-----------+--------+
| id       | asset_id | print_print_id | server_id | status |
+----------+----------+----------------+-----------+--------+
| 15158364 |    26395 |       12063025 |         7 |      1 |
| 15158363 |    26395 |       12063025 |         5 |      1 |
| 15158362 |    26391 |       12063024 |         7 |      1 |
+----------+----------+----------------+-----------+--------+
3 rows in set (0.00 sec)

mysql>
</code>


==== Troubleshooting Replication ====

Seen on Staging "b" server, the master server was an abrupt shutoff without correct poweroff sequence. After the master was brought back online, the following error was observed on the slave:-
<code>
xxxstag_db-b:[(none)] mysql> show slave status \G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.xx.yy.zz
                  Master_User: stag-db-b
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000088
          Read_Master_Log_Pos: 324914788
               Relay_Log_File: stag-db-b-relay-bin.000212
                Relay_Log_Pos: 222731030
        Relay_Master_Log_File: mysql-bin.000087
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: 
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: 
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1062
                   Last_Error: Error 'Duplicate entry '719134' for key 'PRIMARY'' on query. Default database: 'monitoring6'. 
 Query: 'INSERT INTO `timeline_group` (`date_inserted`, `date_start`, `date_updated`) 
VALUES (UTC_TIMESTAMP(), UTC_TIMESTAMP(), UTC_TIMESTAMP())'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 222730884
              Relay_Log_Space: 566625506
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 1062
               Last_SQL_Error: Error 'Duplicate entry '719134' for key 'PRIMARY'' on query. Default database: 'monitor6'. 
Query: 'INSERT INTO `timeline_group` (`date_inserted`, `date_start`, `date_updated`) 
VALUES (UTC_TIMESTAMP(), UTC_TIMESTAMP(), UTC_TIMESTAMP())'
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 1
1 row in set (0.00 sec)

stag-db-b:[(none)] mysql>
</code>

Various posts on the internet suggest adding a skip statement to my.cnf to ignore these errors. 

<code>
slave-skip-errors = 1062
</code>

This was done and the server and replication restarted. The error changed to:-

<code>
                   Last_Errno: 1594
                   Last_Error: Relay log read failure: Could not parse relay log event entry. The possible reasons are: the master's binary log is corrupted 
(you can check this by running 'mysqlbinlog' on the binary log), the slave's relay log is corrupted 
(you can check this by running 'mysqlbinlog' on the relay log), a network problem, or a bug in the master's or slave's MySQL code. 
If you want to check the master's binary log or slave's relay log, you will be able to know their names by issuing 'SHOW SLAVE STATUS' on this slave.
                 Skip_Counter: 0
</code>

This post [[http://www.redips.net/mysql/replication-slave-relay-log-corrupted/]] details the exact problem we had, the suggestion is to discard current relay binlogs and to point slave to the last master binlog position.


Note these two parameters and their values:-
<code>
Relay_Master_Log_File: mysql-bin.000XXXXX
Exec_Master_Log_Pos: 2229XXXXX
</code>

<code>
stag-db-b:[(none)] mysql> stop slave;
 
stag-db-b:[(none)] mysql> reset slave;
 

stag-db-b:[(none)] mysql> change master to master_log_file='mysql-bin.000087', master_log_pos=222944332;
 
stag-db-b:[(none)] mysql> start slave;
</code>


Errors are now cleared and replication is running again, don't forget to remove the skip error line in my.cnf after Seconds_Behind_Master: reaches zero!


==== Running BACKUP from Slave DB ====

Backup Command to run: \\

<code>

innobackupex --user=dbadmin --password=Secret --socket=/run/mysql/mysql.sock --slave-info --safe-slave-backup /mnt/datastore/db-backup/

</code>

Backup Directory: \\

<code>
root@m1b:/mnt/datastore/db-backup# ls -lrth
total 20K
-rw-r--r-- 1 root root   45 Aug  4 05:54 currentbackup-full.txt
-rw-r--r-- 1 root root   45 Aug  4 05:54 lastbackup-full.txt
-rw-r--r-- 1 root root   45 Aug  5 08:10 housekeeping.log
drwxr-xr-x 7 root root 4.0K Aug  5 08:10 2015-08-04_05-00-13
drwxr-xr-x 6 root root 4.0K Aug  5 13:52 2015-08-05_13-51-28
</code>

Backup Completed: \\

<code>
<<snip>>
>> log scanned up to (4112215135501)
xtrabackup: Creating suspend file '/mnt/datastore/db-backup/2015-08-05_13-51-28/xtrabackup_suspended_2' with pid '8996'
>> log scanned up to (4112216371345)

150805 14:37:30  innobackupex: Continuing after ibbackup has suspended
innobackupex:: Slave open temp tables: 0
150805 14:37:30  innobackupex: Starting to lock all tables...
150805 14:37:30  innobackupex: All tables locked and flushed to disk

150805 14:37:30  innobackupex: Starting to backup non-InnoDB tables and files
innobackupex: in subdirectories of '/mnt/datastore/mysql/'
innobackupex: Backing up files '/mnt/datastore/mysql//wm6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (28 files)
innobackupex: Backing up files '/mnt/datastore/mysql//cch6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (23 files)
innobackupex: Backing up files '/mnt/datastore/mysql//expose6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (71 files)
innobackupex: Backing up files '/mnt/datastore/mysql//fp6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (41 files)
innobackupex: Backing up files '/mnt/datastore/mysql//pvp6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (26 files)
>> log scanned up to (4112216377127)
innobackupex: Backing up files '/mnt/datastore/mysql//mysql/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (72 files)
innobackupex: Backing up files '/mnt/datastore/mysql//monitoring6/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (108 files)
innobackupex: Backing up files '/mnt/datastore/mysql//performance_schema/*.{frm,isl,MYD,MYI,MAD,MAI,MRG,TRG,TRN,ARM,ARZ,CSM,CSV,opt,par}' (18 files)
150805 14:37:32  innobackupex: Finished backing up non-InnoDB tables and files

150805 14:37:32  innobackupex: Waiting for log copying to finish

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

xtrabackup: Creating suspend file '/mnt/datastore/db-backup/2015-08-05_13-51-28/xtrabackup_log_copied' with pid '8996'
xtrabackup: Transaction log of lsn (4110938433184) to (4112216377127) was copied.
150805 14:37:33  innobackupex: All tables unlocked
innobackupex:: Starting slave SQL thread

innobackupex: Backup created in directory '/mnt/datastore/db-backup/2015-08-05_13-51-28'
innobackupex: MySQL binlog position: filename 'mysql-bin.000156', position 205
innobackupex: MySQL slave binlog position: master host '10.100.200.11', filename 'mysql-bin.001608', position 102662427
150805 14:37:33  innobackupex: Connection to database server closed
150805 14:37:33  innobackupex: completed OK!
<<snip>>
</code>

Backup Directory Contents:

<code>
root@m1b:/mnt/datastore/db-backup/2015-08-05_13-51-28# ls -lrth
total 2.9G
-rw-r--r-- 1 root root  262 Aug  5 13:51 backup-my.cnf
-rw-r----- 1 root root 1.7G Aug  5 13:51 ibdata1
-rw-r--r-- 1 root root   78 Aug  5 14:37 xtrabackup_slave_info
-rw-r--r-- 1 root root   23 Aug  5 14:37 xtrabackup_binlog_info
drwx------ 2 root root 4.0K Aug  5 14:37 wm6
drwx------ 2 root root 4.0K Aug  5 14:37 cch6
drwx------ 2 root root  16K Aug  5 14:37 exp6
drwx------ 2 root root 4.0K Aug  5 14:37 fp6
drwx------ 2 root root 4.0K Aug  5 14:37 pvp6
drwxr-xr-x 2 root root 4.0K Aug  5 14:37 mysql
drwx------ 2 root root  12K Aug  5 14:37 monitor6
drwxr-xr-x 2 root root 4.0K Aug  5 14:37 performance_schema
drwxr-xr-x 2 root root 4.0K Aug  5 14:37 binlog
-rw-r----- 1 root root 1.2G Aug  5 14:37 xtrabackup_logfile
-rw-r----- 1 root root  101 Aug  5 14:37 xtrabackup_checkpoints
-rw-r--r-- 1 root root   13 Aug  5 14:37 xtrabackup_binary
</code>

Slave Info: \\

<code>


root@m1b:/mnt/datastore/db-backup/2015-08-05_13-51-28# cat xtrabackup_slave_info
CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.001608', MASTER_LOG_POS=102662427
</code>

APPLY LOG: \\

<code>
root@m1b:/mnt/datastore/db-backup# innobackupex --apply-log 2015-08-05_13-51-28/

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

IMPORTANT: Please check that the apply-log run completes successfully.
           At the end of a successful apply-log run innobackupex
           prints "completed OK!".
150805 14:43:30  innobackupex: Starting ibbackup with command: xtrabackup_55  --defaults-file="/mnt/datastore/db-backup/2015-08-05_13-51-28/backup-my.cnf"  --defaults-group="mysqld" --prepare --target-dir=/mnt/datastore/db-backup/2015-08-05_13-51-28 --tmpdir=/tmp

xtrabackup_55 version 2.1.7 for Percona Server 5.5.35 Linux (x86_64) (revision id: 721)
xtrabackup: cd to /mnt/datastore/db-backup/2015-08-05_13-51-28
xtrabackup: This target seems to be not prepared yet.
xtrabackup: xtrabackup_logfile detected: size=1437696000, start_lsn=(4110938433184)
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 1437696000
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 1
xtrabackup:   innodb_log_file_size = 1437696000
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
150805 14:43:30 InnoDB: The InnoDB memory heap is disabled
150805 14:43:30 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150805 14:43:30 InnoDB: Compressed tables use zlib 1.2.3
150805 14:43:30 InnoDB: Initializing buffer pool, size = 100.0M
150805 14:43:30 InnoDB: Completed initialization of buffer pool
150805 14:43:30 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 4110938433184
150805 14:43:30  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Doing recovery: scanned up to log sequence number 4110943675904 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110948918784 (0 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110954161664 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110959404544 (1 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110964647424 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110969890304 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110975133184 (2 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110980376064 (3 %)
150805 14:43:32  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4110985618944 (3 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110990861824 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 4110996104704 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111001347584 (4 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111006590464 (5 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111011833344 (5 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111017076224 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111022319104 (6 %)
150805 14:43:34  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111027561984 (6 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111032804864 (7 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111038047744 (7 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111043290624 (8 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111048533504 (8 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111053776384 (9 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111059019264 (9 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111064262144 (9 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111069505024 (10 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111074747904 (10 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111079990784 (11 %)
150805 14:43:38  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111085233664 (11 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111090476544 (11 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111095719424 (12 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111100962304 (12 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111106205184 (13 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111111448064 (13 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111116690944 (13 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111121933824 (14 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111127176704 (14 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111132419584 (15 %)
150805 14:43:43  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111137662464 (15 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111142905344 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111148148224 (16 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111153391104 (16 %)
150805 14:43:48  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111158633984 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111163876864 (17 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111169119744 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111174362624 (18 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111179605504 (18 %)
150805 14:43:54  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111184848384 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111190091264 (19 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111195334144 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111200577024 (20 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111205819904 (20 %)
150805 14:43:59  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111211062784 (21 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111216305664 (21 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111221548544 (22 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111226791424 (22 %)
150805 14:44:03  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111232034304 (22 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111237277184 (23 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111242520064 (23 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111247762944 (24 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111253005824 (24 %)
150805 14:44:08  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111258248704 (25 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111263491584 (25 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111268734464 (25 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111273977344 (26 %)
150805 14:44:16  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111279220224 (26 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111284463104 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111289705984 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111294948864 (27 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111300191744 (28 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111305434624 (28 %)
150805 14:44:20  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111310677504 (29 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111315920384 (29 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111321163264 (29 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111326406144 (30 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111331649024 (30 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111336891904 (31 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111342134784 (31 %)
150805 14:44:25  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111347377664 (32 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111352620544 (32 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111357863424 (32 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111363106304 (33 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111368349184 (33 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111373592064 (34 %)
150805 14:44:28  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111378834944 (34 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111384077824 (34 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111389320704 (35 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111394563584 (35 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111399806464 (36 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111405049344 (36 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111410292224 (36 %)
150805 14:44:31  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111415535104 (37 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111420777984 (37 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111426020864 (38 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111431263744 (38 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111436506624 (38 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111441749504 (39 %)
150805 14:44:34  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111446992384 (39 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111452235264 (40 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111457478144 (40 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111462721024 (41 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111467963904 (41 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111473206784 (41 %)
150805 14:44:41  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111478449664 (42 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111483692544 (42 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111488935424 (43 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111494178304 (43 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111499421184 (43 %)
150805 14:44:48  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111504664064 (44 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111509906944 (44 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111515149824 (45 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111520392704 (45 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111525635584 (45 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111530878464 (46 %)
150805 14:44:52  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111536121344 (46 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111541364224 (47 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111546607104 (47 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111551849984 (48 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111557092864 (48 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111562335744 (48 %)
150805 14:44:56  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111567578624 (49 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111572821504 (49 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111578064384 (50 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111583307264 (50 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111588550144 (50 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111593793024 (51 %)
150805 14:44:59  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111599035904 (51 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111604278784 (52 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111609521664 (52 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111614764544 (52 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111620007424 (53 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111625250304 (53 %)
150805 14:45:03  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111630493184 (54 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111635736064 (54 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111640978944 (54 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111646221824 (55 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111651464704 (55 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111656707584 (56 %)
150805 14:45:09  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111661950464 (56 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111667193344 (57 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111672436224 (57 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111677679104 (57 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111682921984 (58 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111688164864 (58 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111693407744 (59 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111698650624 (59 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111703893504 (59 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111709136384 (60 %)
150805 14:45:11  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111714379264 (60 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111719622144 (61 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111724865024 (61 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111730107904 (61 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111735350784 (62 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111740593664 (62 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111745836544 (63 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111751079424 (63 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111756322304 (64 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111761565184 (64 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111766808064 (64 %)
150805 14:45:15  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111772050944 (65 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111777293824 (65 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111782536704 (66 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111787779584 (66 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111793022464 (66 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111798265344 (67 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111803508224 (67 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111808751104 (68 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111813993984 (68 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111819236864 (68 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111824479744 (69 %)
150805 14:45:17  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111829722624 (69 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111834965504 (70 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111840208384 (70 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111845451264 (70 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111850694144 (71 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111855937024 (71 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111861179904 (72 %)
150805 14:45:20  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111866422784 (72 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111871665664 (73 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111876908544 (73 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111882151424 (73 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111887394304 (74 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111892637184 (74 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111897880064 (75 %)
150805 14:45:22  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111903122944 (75 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111908365824 (75 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111913608704 (76 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111918851584 (76 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111924094464 (77 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111929337344 (77 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111934580224 (77 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111939823104 (78 %)
150805 14:45:27  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111945065984 (78 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111950308864 (79 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111955551744 (79 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111960794624 (80 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111966037504 (80 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111971280384 (80 %)

150805 14:45:31  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4111976523264 (81 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111981766144 (81 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111987009024 (82 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111992251904 (82 %)
InnoDB: Doing recovery: scanned up to log sequence number 4111997494784 (82 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112002737664 (83 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112007980544 (83 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112013223424 (84 %)
150805 14:45:35  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112018466304 (84 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112023709184 (84 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112028952064 (85 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112034194944 (85 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112039437824 (86 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112044680704 (86 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112049923584 (86 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112055166464 (87 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112060409344 (87 %)
150805 14:45:41  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112065652224 (88 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112070895104 (88 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112076137984 (89 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112081380864 (89 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112086623744 (89 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112091866624 (90 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112097109504 (90 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112102352384 (91 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112107595264 (91 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112112838144 (91 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112118081024 (92 %)
150805 14:45:45  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112123323904 (92 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112128566784 (93 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112133809664 (93 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112139052544 (93 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112144295424 (94 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112149538304 (94 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112154781184 (95 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112160024064 (95 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112165266944 (96 %)
150805 14:45:50  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112170509824 (96 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112175752704 (96 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112180995584 (97 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112186238464 (97 %)
150805 14:45:52  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112191481344 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112196724224 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112201967104 (98 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112207209984 (99 %)
InnoDB: Doing recovery: scanned up to log sequence number 4112212452864 (99 %)
150805 14:45:57  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: Doing recovery: scanned up to log sequence number 4112216377127 (99 %)
150805 14:45:59  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
InnoDB: Apply batch completed
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 102662427, file name mysql-bin.001608
InnoDB: and relay log file
InnoDB: position 102662573, file name /mnt/datastore/mysql/relay-bin.000015
InnoDB: Last MySQL binlog file position 0 415037448, file name /mnt/datastore/mysql/binlog/mysql-bin.000296
150805 14:46:00  InnoDB: Waiting for the background threads to start
150805 14:46:01 Percona XtraDB (http://www.percona.com) 5.5.35-33.0 started; log sequence number 4112216377127

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 415037448, file name /mnt/datastore/mysql/binlog/mysql-bin.000296

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
150805 14:46:01  InnoDB: Starting shutdown...
150805 14:46:05  InnoDB: Shutdown completed; log sequence number 4112216378085

150805 14:46:05  innobackupex: Restarting xtrabackup with command: xtrabackup_55  --defaults-file="/mnt/datastore/db-backup/2015-08-05_13-51-28/backup-my.cnf"  --defaults-group="mysqld" --prepare --target-dir=/mnt/datastore/db-backup/2015-08-05_13-51-28 --tmpdir=/tmp
for creating ib_logfile*

xtrabackup_55 version 2.1.7 for Percona Server 5.5.35 Linux (x86_64) (revision id: 721)
xtrabackup: cd to /mnt/datastore/db-backup/2015-08-05_13-51-28
xtrabackup: This target seems to be already prepared.
xtrabackup: notice: xtrabackup_logfile was already used to '--prepare'.
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 536870912
xtrabackup: using the following InnoDB configuration for recovery:
xtrabackup:   innodb_data_home_dir = ./
xtrabackup:   innodb_data_file_path = ibdata1:10M:autoextend
xtrabackup:   innodb_log_group_home_dir = ./
xtrabackup:   innodb_log_files_in_group = 2
xtrabackup:   innodb_log_file_size = 536870912
xtrabackup: Starting InnoDB instance for recovery.
xtrabackup: Using 104857600 bytes for buffer pool (set by --use-memory parameter)
150805 14:46:05 InnoDB: The InnoDB memory heap is disabled
150805 14:46:05 InnoDB: Mutexes and rw_locks use GCC atomic builtins
150805 14:46:05 InnoDB: Compressed tables use zlib 1.2.3
150805 14:46:05 InnoDB: Initializing buffer pool, size = 100.0M
150805 14:46:05 InnoDB: Completed initialization of buffer pool
150805 14:46:05  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 512 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500
150805 14:46:07  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 512 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500
150805 14:46:08 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
150805 14:46:08  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 102662427, file name mysql-bin.001608
InnoDB: and relay log file
InnoDB: position 102662573, file name /mnt/datastore/mysql/relay-bin.000015
InnoDB: Last MySQL binlog file position 0 415037448, file name /mnt/datastore/mysql/binlog/mysql-bin.000296
150805 14:46:08  InnoDB: Waiting for the background threads to start
150805 14:46:09 Percona XtraDB (http://www.percona.com) 5.5.35-33.0 started; log sequence number 4112216378380

[notice (again)]
  If you use binary log and don't use any hack of group commit,
  the binary log position seems to be:
InnoDB: Last MySQL binlog file position 0 415037448, file name /mnt/datastore/mysql/binlog/mysql-bin.000296

xtrabackup: starting shutdown with innodb_fast_shutdown = 1
150805 14:46:09  InnoDB: Starting shutdown...
150805 14:46:13  InnoDB: Shutdown completed; log sequence number 4112216378830
150805 14:46:13  innobackupex: completed OK!

</code>

RSYNC to C Server:

<code>
root@m1b:/mnt/datastore/db-backup# rsync -vr 2015-08-05_13-51-28 10.100.200.13::db-backup-B-server 

sent 290479725953 bytes  received 15495 bytes  53877351.66 bytes/sec
total size is 290444217369  speedup is 1.00

</code>