Table of Contents
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
MASTER config
On Master, create slave user and permissions:-
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>
Edit my.cnf to let mysql know about the binlogs to create:-
# 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
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:-
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>
SLAVE Config
Edit my.cnf to configure the replication filters:
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_%
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
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>
From system error log:-
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
Replication Mode
Currently set to:-
mysql> show variables like "binlog_format"; +---------------+-------+ | Variable_name | Value | +---------------+-------+ | binlog_format | MIXED | +---------------+-------+ 1 row in set (0.00 sec) mysql>
Find last binlog entry
This is the last point in binlog being written to, it is NOT the position to use for starting replication.
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>
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.
root@m1b:/mnt/datastore/mysql# cat xtrabackup_binlog_info mysql-bin.000296 415038146 root@m1b:/mnt/datastore/mysql#
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;
May be xtrabackup_binlog_pos_innodb
root@db01b:/mnt/datastore/mysql# cat xtrabackup_binlog_pos_innodb /data/mysql/binlog/mysql-bin.000999 203005933 root@db01b:/mnt/datastore/mysql#
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.
dbadmin@infra-jenkins-rel01:~$ ssh root@52.aa.bb.cc -R 8888:10.xx.yy.zz:3306 -N
To enable this open /etc/ssh/sshd_config and add the following line somewhere in that config file.
GatewayPorts yes
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.
root@prod-db01d:/data/mysql# more xtrabackup_slave_info CHANGE MASTER TO MASTER_LOG_FILE='mysql-bin.000370', MASTER_LOG_POS=326784188
Change below values as required, matching MASTER_LOG_FILE and MASTER_LOG_POS from previous statement.
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;
Testing replication
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
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.
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>
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:-
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>
Various posts on the internet suggest adding a skip statement to my.cnf to ignore these errors.
slave-skip-errors = 1062
This was done and the server and replication restarted. The error changed to:-
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
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:-
Relay_Master_Log_File: mysql-bin.000XXXXX Exec_Master_Log_Pos: 2229XXXXX
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;
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:
innobackupex --user=dbadmin --password=Secret --socket=/run/mysql/mysql.sock --slave-info --safe-slave-backup /mnt/datastore/db-backup/
Backup Directory:
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
Backup Completed:
<<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>>
Backup Directory Contents:
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
Slave Info:
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
APPLY LOG:
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!
RSYNC to C Server:
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