Waiting for binlog lock

[monty solomon]

Some slaves are behind and hung with status "Waiting for binlog lock" while xtrabackup is running.

Server version: 5.6.25-73.1-log Percona Server (GPL), Release 73.1, Revision 07b797f

xtrabackup version 2.2.12 based on MySQL server 5.6.24 Linux (x86_64) (revision id: 8726828)

root 5269 5243 0 05:00 ? 00:00:00 perl /usr/bin/innobackupex --slave-info --stream=tar ./
root 5289 5269 0 05:00 ? 00:00:22 xtrabackup --defaults-group=mysqld --backup --suspend-at-end --target-dir=/opt/mysql/dblogs1/comments-p0/tmp --innodb_data_file_path=ibdata1:12M:autoextend --tmpdir=/opt/mysql/dblogs1/comments-p0/tmp --extra-lsndir=/opt/mysql/dblogs1/comments-p0/tmp --stream=tar

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: featherwoman
                  Master_User: SUSR_Repl
                  Master_Port: 3306
                Connect_Retry: 15
              Master_Log_File: bin.013900
          Read_Master_Log_Pos: 76892
               Relay_Log_File: relay.041706
                Relay_Log_Pos: 802598
        Relay_Master_Log_File: bin.013898
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 802441
              Relay_Log_Space: 1867701
              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: 2393
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 1285626324
                  Master_UUID: 9142b755-ac30-11e4-ab03-0e946fe5c82d
             Master_Info_File: /opt/mysql/dbdata1/comments-p0/master.info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Waiting for binlog lock
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

mysql> show processlist;
+---------+----------------+---------------------+-----------+---------+---------+----------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+---------+----------------+---------------------+-----------+---------+---------+----------------------------------+------------------+-----------+---------------+
| 5 | system user | | NULL | Connect | 6845243 | Waiting for master to send event | NULL | 0 | 0 |
| 6 | system user | | NULL | Connect | 2654 | Waiting for binlog lock | NULL | 0 | 0 |
| 4429539 | SUSR_Monitor | 172.16.45.179:50025 | NULL | Sleep | 22 | | NULL | 0 | 0 |
| 6922906 | root | localhost | NULL | Sleep | 2654 | | NULL | 0 | 0 |
| 6925239 | SUSR_Heartbeat | 127.0.0.1:38044 | NULL | Sleep | 0 | | NULL | 0 | 0 |
| 6925385 | SUSR_Heartbeat | 127.0.0.1:38302 | NULL | Sleep | 0 | | NULL | 403 | 403 |
| 6925532 | SUSR_Monitor | 172.16.6.27:12112 | mysql | Sleep | 164 | | NULL | 0 | 0 |
| 6925676 | SUSR_Monitor | 172.18.7.134:58842 | mysql | Sleep | 22 | | NULL | 0 | 0 |
| 6925697 | root | localhost | NULL | Query | 0 | init | show processlist | 0 | 0 |
| 6925701 | SUSR_Heartbeat | localhost | heartbeat | Sleep | 0 | | NULL | 1 | 1 |
+---------+----------------+---------------------+-----------+---------+---------+----------------------------------+------------------+-----------+---------------+
10 rows in set (0.00 sec)

[monty solomon (monty+launchpad)]

This happened again on two (2) different clusters in the past week.

[Shahriyar Rzayev (rzayev-sehriyar)]

As documentation noted:

https://www.percona.com/doc/percona-server/5.6/management/backup_locks.html

"Connections that are currently blocked on the global binlog lock can be identified by the Waiting for binlog lock status in PROCESSLIST."

[monty solomon (monty+launchpad)]

The only connection waiting on the global binlog lock is the slave sql thread.

[Laurynas Biveinis (laurynas-biveinis)]

Isn't XtraBackup binlog lock duration supposed to be short?

[XieAn (xiepaup)]

I have Percona Server 5.6.27-76.0-log Source distribution Meet the same problem

For Show Processlist :
mysql> show processlist;
+---------+-------------+-----------+------------+---------+-------+----------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+---------+-------------+-----------+------------+---------+-------+----------------------------------+------------------+-----------+---------------+
| 4613465 | system user | | NULL | Connect | 65348 | Waiting for master to send event | NULL | 0 | 0 |
| 4613466 | system user | | NULL | Connect | 18510 | Waiting for binlog lock | NULL | 0 | 0 |
| 4631056 | dbbackup | localhost | NULL | Sleep | 18510 | | NULL | 0 | 0 |

And Show Slave status：
mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 10.205.138.14
                  Master_User: replic
                  Master_Port: 3306
                Connect_Retry: 10
              Master_Log_File: mysql-bin.002101
          Read_Master_Log_Pos: 48324005
               Relay_Log_File: relay-bin.006273
                Relay_Log_Pos: 23550748
        Relay_Master_Log_File: mysql-bin.002098
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB:
          Replicate_Ignore_DB:
           Replicate_Do_Table:
       Replicate_Ignore_Table:
      Replicate_Wild_Do_Table:
  Replicate_Wild_Ignore_Table:
                   Last_Errno: 0
                   Last_Error:
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 23550585
              Relay_Log_Space: 1658935960
              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: 18283
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error:
               Last_SQL_Errno: 0
               Last_SQL_Error:
  Replicate_Ignore_Server_Ids:
             Master_Server_Id: 138143306
                  Master_UUID: 0aec6a3d-3074-11e6-8ed0-a0369f7c3f90
             Master_Info_File: mysql.slave_master_info
                    SQL_Delay: 0
          SQL_Remaining_Delay: NULL
      Slave_SQL_Running_State: Waiting for binlog lock
           Master_Retry_Count: 86400
                  Master_Bind:
      Last_IO_Error_Timestamp:
     Last_SQL_Error_Timestamp:
               Master_SSL_Crl:
           Master_SSL_Crlpath:
           Retrieved_Gtid_Set:
            Executed_Gtid_Set:
                Auto_Position: 0
1 row in set (0.00 sec)

Look For Backup logs,The backup...

[XieAn (xiepaup)]

Oh ! , this may the use of xtrabackup problem !, for there are two instance in the same machine,and one data size about 50GB,other 500GB ; the bigger instance start backup at 2 clock,and the smaller one start at 3 clock ,so this case this phenomenon ！！

[monty solomon (monty+launchpad)]

Server version: 5.7.18-15-log Percona Server (GPL), Release 15, Revision bff2cd9

mysql> show processlist;
+----------+-----------------+---------------------+---------------------+---------+---------+---------------------------------------------+------------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----------+-----------------+---------------------+---------------------+---------+---------+---------------------------------------------+------------------------+-----------+---------------+
| 16985924 | system user | | NULL | Connect | 2398692 | Waiting for master to send event | NULL | 0 | 0 |
| 16985925 | system user | | NULL | Connect | 44338 | Waiting for dependent transaction to commit | NULL | 0 | 0 |
| 16985926 | system user | | NULL | Connect | 44339 | Waiting for binlog lock | NULL | 0 | 0 |
| 16985927 | system user | | NULL | Connect | 44338 | Waiting for preceding transaction to commit | NULL | 0 | 0 |
| 16985928 | system user | | NULL | Connect | 44344 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 16985929 | system user | | NULL | Connect | 62338 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20256033 | root | localhost | NULL | Query | 44338 | Waiting for binlog lock | LOCK BINLOG FOR BACKUP | 0 | 0 |
| 20311329 | root | localhost | NULL | Query | 4605 | Killing slave | stop slave | 0 | 0 |
| 20311662 | root | localhost | NULL | Query | 4416 | starting | FLUSH LOCAL LOGS | 0 | 0 |
| 20317060 | SUSR_Heartbeat | 127.0.0.1:58334 | NULL | Sleep | 0 | | NULL | 0 | 0 |
| 20317427 | SUSR_Monitor | 172.16.44.164:49158 | mysql | Sleep | 62 | | NULL | 0 | 0 |
| 20317620 | SUSR_Monitor | 172.18.25.89:19392 | mysql | Sleep | 140 | | NULL | 0 | 0 |
| 20317928 | SUSR_Heartbeat | 127.0.0.1:60094 | NULL | Sleep | 1 | | NULL | 0 | ...

[monty solomon (monty+launchpad)]

Killing 20256033 (LOCK BINLOG FOR BACKUP) enabled the slave to catch up.

[monty solomon (monty+launchpad)]

mysql> show processlist;
+----------+-----------------+---------------------+---------------------+---------+---------+---------------------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----------+-----------------+---------------------+---------------------+---------+---------+---------------------------------------------+------------------+-----------+---------------+
| 16985924 | system user | | NULL | Connect | 2398885 | Waiting for master to send event | NULL | 0 | 0 |
| 20317060 | SUSR_Heartbeat | 127.0.0.1:58334 | NULL | Sleep | 0 | | NULL | 0 | 0 |
| 20317427 | SUSR_Monitor | 172.16.44.164:49158 | mysql | Sleep | 12 | | NULL | 0 | 0 |
| 20317928 | SUSR_Heartbeat | 127.0.0.1:60094 | NULL | Sleep | 0 | | NULL | 0 | 0 |
| 20317935 | SUSR_Heartbeat | 127.0.0.1:60112 | NULL | Sleep | 221 | | NULL | 0 | 0 |
| 20317962 | root | localhost | NULL | Query | 0 | starting | show processlist | 0 | 0 |
| 20318067 | root | localhost | NULL | Sleep | 2 | | NULL | 0 | 0 |
| 20318158 | root | localhost | NULL | Sleep | 13 | | NULL | 0 | 0 |
| 20318168 | system user | | NULL | Connect | 0 | Waiting for dependent transaction to commit | NULL | 0 | 0 |
| 20318169 | system user | | NULL | Connect | 44513 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318170 | system user | | NULL | Connect | 44513 | System lock | NULL | 0 | 0 |
| 20318171 | system user | | NULL | Connect | 44517 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318172 | system user | | NULL | Connect | 44520 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318173 | SUSR_Monitor | 172.18.25.89:21144 | mysql | Sleep | 3 | | NULL | ...

[monty solomon (monty+launchpad)]

mysql> show processlist;
+----------+-----------------+---------------------+---------------------+---------+------+--------------------------------------------------------+------------------+-----------+---------------+
| Id | User | Host | db | Command | Time | State | Info | Rows_sent | Rows_examined |
+----------+-----------------+---------------------+---------------------+---------+------+--------------------------------------------------------+------------------+-----------+---------------+
| 20317928 | SUSR_Heartbeat | 127.0.0.1:60094 | NULL | Sleep | 1 | | NULL | 0 | 0 |
| 20318198 | SUSR_Heartbeat | 127.0.0.1:60854 | NULL | Sleep | 1 | | NULL | 0 | 0 |
| 20318214 | system user | | NULL | Connect | 382 | Waiting for master to send event | NULL | 0 | 0 |
| 20318215 | system user | | NULL | Connect | 0 | Slave has read all relay log; waiting for more updates | NULL | 0 | 0 |
| 20318216 | system user | | NULL | Connect | 0 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318217 | system user | | NULL | Connect | 50 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318218 | system user | | NULL | Connect | 97 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318219 | system user | | NULL | Connect | 877 | Waiting for an event from Coordinator | NULL | 0 | 0 |
| 20318298 | SUSR_Heartbeat | 127.0.0.1:33028 | NULL | Sleep | 308 | | NULL | 0 | 0 |
| 20318663 | SUSR_Monitor | 172.18.25.89:19438 | mysql | Sleep | 120 | | NULL | 0 | 0 |
| 20318765 | SUSR_Monitor | 172.16.44.164:38416 | mysql | Sleep | 52 | | NULL | 0 | 0 |
| 20318812 | root | localhost | NULL | Query | 0 | starting | show processlist | 0 | 0 |
| 20318820 | SUSR_Heartbeat | localhost | heartbeat | Sleep | 1 | | NULL | 1 | 1 |
+----------+-----------------+---------...

[monty solomon (monty+launchpad)]

xtrabackup version 2.4.7 based on MySQL server 5.7.13 Linux (x86_64) (revision id: 6f7a799)

[Shahriyar Rzayev (rzayev-sehriyar)]

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