Backup locks do not guarantee consistent SHOW SLAVE STATUS with binary log disabled

Bug #1358836 reported by Andrew Garner
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Alexey Kopytov
5.1
Invalid
Undecided
Unassigned
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
High
Alexey Kopytov

Bug Description

An active binlog lock via LOCK BINLOG FOR BACKUP does not prevent Exec_Master_Log_Pos from incrementing. This seems to be contrary to the documented behavior here: http://www.percona.com/doc/percona-server/5.6/management/backup_locks.html#lock-binlog-for-backup

The documentation seems to indicate that LOCK BINLOG FOR BACKUP will block changes that will increment the binary log position or Exec_Master_Log_Pos.

Expected behavior:
LOCK BINLOG FOR BACKUP will provide a consistent Relay_Master_Log_File / Exec_Master_Log_Pos while the binlog lock is held.

Observed behavior:
DML to InnoDB tables increments Exec_Master_Log_Pos in spite of LOCK TABLES FOR BACKUP / LOCK BINLOG FOR BACKUP being held.

Tested on: 5.6.19-67.0-log (Percona Server (GPL), Release 67.0, Revision 618)

In this case, the situation was an LVM snapshot backup where backup locks were being explored as an alternative to FTWRL when using Percona-Server.

The basic pattern was:

mysql[master]> CREATE DATABASE IF NOT EXISTS `test`;
Query OK, 1 row affected (0.00 sec)
mysql[master]> CREATE TABLE IF NOT EXISTS `test`.`kv` (id int primary key auto_increment, data varchar(32)) ENGINE=InnoDB;
Query OK, 0 rows affected (0.01 sec)

mysql[slave]> LOCK TABLES FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)
mysql[slave]> LOCK BINLOG FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)
mysql[slave]> \P grep Exec_Master_Log_Pos PAGER set to 'grep Exec_Master_Log_Pos'
mysql[slave]> SHOW SLAVE STATUS\G
          Exec_Master_Log_Pos: 7545
1 row in set (0.00 sec)

mysql[master]> INSERT INTO `test`.`kv` (data) SELECT MD5('foo');

mysql[slave]> SHOW SLAVE STATUS\G
          Exec_Master_Log_Pos: 7801
1 row in set (0.00 sec)

However, if this was MyISAM the backup or binlog lock seems to protect this position:

mysql[master]> ALTER TABLE `test`.`kv` ENGINE=MyISAM;
Query OK, 1 row affected (0.00 sec)
Records: 1 Duplicates: 0 Warnings: 0

mysql[slave]> SHOW PROCESSLIST;
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------------------------+-----------+---------------+
| 1 | system user | | NULL | Connect | 132 | Waiting for master to send event | NULL | 0 | 0 |
| 2 | system user | | | Connect | 7 | Waiting for backup lock | ALTER TABLE `test`.`kv` ENGINE = MyISAM | 0 | 0 |
| 3 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST | 0 | 0 |
+----+-------------+-----------+------+---------+------+----------------------------------+-----------------------------------------+-----------+---------------+
3 rows in set (0.00 sec)

mysql[slave]> UNLOCK TABLES;
Query OK, 0 rows affected (0.00 sec)

mysql[sandbox]> SHOW PROCESSLIST;
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
| 1 | system user | | NULL | Connect | 328 | Waiting for master to send event | NULL | 0 | 0 |
| 2 | system user | | NULL | Connect | 203 | Waiting for binlog lock | NULL | 0 | 0 |
| 3 | root | localhost | NULL | Query | 0 | init | SHOW PROCESSLIST | 0 | 0 |
+----+-------------+-----------+------+---------+------+----------------------------------+------------------+-----------+---------------+
3 rows in set (0.00 sec)

There's a more serious problem here if log-slave-updates is enabled on the slave. In that case replication does block on a binlog lock (even for an insert to an InnoDB table), but then running SHOW SLAVE STATUS will hang in the original connection that holds a binlog lock. This is essentially the symptoms of http://bugs.mysql.com/bug.php?id=70307. I suspect this is a separate bug entirely.

Related branches

Revision history for this message
Alexey Kopytov (akopytov) wrote :

We have a regression test case covering this very scenario, i.e. the one that checks that a DML against an InnoDB table on the master is blocked on an active BINLOG lock when being replayed on the slave (mysql-test/suite/rpl/t/rpl_backup_locks.test). The test case passes with all values of binlog_format.

Which means that either something is different between your environment and the one that the test case sets up, or there's a mistake in your tests.

Can you show the full output of SHOW SLAVE STATUS and the contents of the relay log on the slave corresponding to "before" and "after" values of Exec_Master_Log_Pos?

Changed in percona-server:
status: New → Incomplete
Revision history for this message
Andrew Garner (muzazzi) wrote :
Download full text (11.8 KiB)

Hmm. Looking at the test it seems to stop the slave, acquire the locks, restarts the slave and check that the event blocks. If I do the same, I do see the desired behavior:

mysql[master]> SHOW CREATE TABLE foo\G
*************************** 1. row ***************************
       Table: foo
Create Table: CREATE TABLE `foo` (
  `id` int(11) DEFAULT NULL
) ENGINE=InnoDB DEFAULT CHARSET=latin1
1 row in set (0.00 sec)

mysql[master]> truncate table foo;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> stop slave;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> LOCK TABLES FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> LOCK BINLOG FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)

mysql[master]> insert into foo values (1);
Query OK, 1 row affected (0.00 sec)

mysql[slave]> start slave;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> SHOW PROCESSLIST\G
*************************** 1. row ***************************
           Id: 15
         User: root
         Host: localhost
           db: NULL
      Command: Query
         Time: 0
        State: init
         Info: SHOW PROCESSLIST
    Rows_sent: 0
Rows_examined: 0
*************************** 2. row ***************************
           Id: 19
         User: system user
         Host:
           db: NULL
      Command: Connect
         Time: 15
        State: Waiting for master to send event
         Info: NULL
    Rows_sent: 0
Rows_examined: 0
*************************** 3. row ***************************
           Id: 20
         User: system user
         Host:
           db: NULL
      Command: Connect
         Time: 15
        State: Waiting for binlog lock
         Info: NULL
    Rows_sent: 0
Rows_examined: 0
3 rows in set (0.00 sec)

mysql[slave]> unlock tables;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> unlock binlog;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> show processlist\G
*************************** 1. row ***************************
           Id: 15
         User: root
         Host: localhost
           db: NULL
      Command: Query
         Time: 0
        State: init
         Info: show processlist
    Rows_sent: 0
Rows_examined: 0
*************************** 2. row ***************************
           Id: 19
         User: system user
         Host:
           db: NULL
      Command: Connect
         Time: 125
        State: Waiting for master to send event
         Info: NULL
    Rows_sent: 0
Rows_examined: 0
*************************** 3. row ***************************
           Id: 20
         User: system user
         Host:
           db: NULL
      Command: Connect
         Time: 53
        State: Slave has read all relay log; waiting for the slave I/O thread to update it
         Info: NULL
    Rows_sent: 0
Rows_examined: 0
3 rows in set (0.00 sec)

However, if I do not stop the slave and just acquire locks then this does not work for innodb tables:

mysql[master]> truncate table foo;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> LOCK TABLES FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> LOCK BINLOG FOR BACKUP;
Query OK, 0 rows affected (0.00 sec)

mysql[slave]> SHOW SLAVE STATUS\G
*********...

Changed in percona-server:
status: Incomplete → New
Revision history for this message
Alexey Kopytov (akopytov) wrote :

Thanks, I can reproduce it now. The reason it was not reproducible in the MTR test is that MTR sets up the slave with binary log and log_slave_updates enabled by default. With those options disabled and slave restarts removed, the insert is indeed not blocked by an active BINLOG lock.

I could also reproduce the lock issue with SHOW SLAVE STATUS, but will report it separately.

summary: - Backup locks do not guarantee consistent SHOW SLAVE STATUS
+ Backup locks do not guarantee consistent SHOW SLAVE STATUS with binary
+ log disabled
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.