[DOC] Innobackupex point-in-time-recovery log start-pos explanation improvement

[Diego Sainz]

[In:Percona XtraBackup Documentation]

URL https://www.percona.com/doc/percona-xtrabackup/2.2/innobackupex/pit_recovery_ibk.html

The documentation states that the exact position of the backup is contained in the file xtrabackup_binlog_info.

$ cat /path/to/backup/xtrabackup_binlog_info
mysql-bin.000003 57

Later it states that "[...] the next step is extracting the queries from the binary log with mysqlbinlog starting from the position of the snapshot" by running the command

$ mysqlbinlog binlogs... --start-position=57 > mybinlog.sql

But this would replay again the transaction #57, that is the transaction that the backup is from.

Wouldn't start-position need to be the backup position + 1 (in this case 58) ?

[Nilnandan Joshi (nilnandan-joshi)]

Hi,

Start position is not needed to set backup position +1. Because, when you take a backup, in xtrabackup_binlog_info file, next position will be saved. i.e see here,

Before backup, the last position of binlog file was 1096,

root@desktop:/var/lib/mysql# mysqlbinlog mysql-bin.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
...
..
.
# at 1096
#150721 11:07:28 server id 1 end_log_pos 1127 CRC32 0xd70d67a0 Xid = 143
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
root@desktop:/var/lib/mysql#

When I take a backup and check xtrabackup_binlog_info file, the position was 1127. This position is not in binlog file.

root@desktop:/home/nilnandan/backup/2015-07-21_11-10-53# cat xtrabackup_binlog_info
mysql-bin.000001 1127
root@desktop:/home/nilnandan/backup/2015-07-21_11-10-53#

to make further test, I added one record and check binlog file again,

root@desktop:/var/lib/mysql# mysqlbinlog mysql-bin.000001
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4
...
..
.
# at 1096
#150721 11:07:28 server id 1 end_log_pos 1127 CRC32 0xd70d67a0 Xid = 143
COMMIT/*!*/;
# at 1127
#150721 11:42:49 server id 1 end_log_pos 1206 CRC32 0x5388ac06 Query thread_id=40 exec_time=0 error_code=0
SET TIMESTAMP=1437459169/*!*/;
BEGIN
/*!*/;
# at 1206
#150721 11:42:49 server id 1 end_log_pos 1315 CRC32 0x8a641ac8 Query thread_id=40 exec_time=0 error_code=0
SET TIMESTAMP=1437459169/*!*/;
insert into nil values (6, 'joshi')
/*!*/;
# at 1315
#150721 11:42:49 server id 1 end_log_pos 1346 CRC32 0x333e85a0 Xid = 161
COMMIT/*!*/;
DELIMITER ;
# End of log file
ROLLBACK /* added by mysqlbinlog */;
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
root@desktop:/var/lib/mysql#

You can see that 1127 is nothing but Begin statement. I hope this clarified everything.

[Diego Sainz (diego-sainz)]

Hi Nilnandan,

You are right, thanks for such a quick reply.

[Shahriyar Rzayev (rzayev-sehriyar)]

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