Binlog rotation blocks server

[Christian]

Most of the time when binlogs get rotated (automatic or manual), the server blocks all other queries for a couple of seconds (4-15s).

Server version: 5.7.11-4-log Percona Server (GPL), Release '4', Revision '5c940e1'

mysql> flush logs;
Query OK, 0 rows affected (4.24 sec)

We are also running a couple of servers with
Server version: 5.6.21-70.0-log Percona Server (GPL), Release 70.0, Revision 688
and did not experience this issue.

--- Hardware ---
2x CPU E5-2630 v3 @ 2.40GHz
64GB RAM
SSD DC S3500 Series 800 GB, no RAID

--- Config ---
[mysql]

# CLIENT #
port = 3306
socket = /var/run/mysqld/mysqld.sock
default-character-set = utf8mb4

[mysqld]

# GENERAL #
user = mysql
default_storage_engine = InnoDB
socket = /var/run/mysqld/mysqld.sock
pid-file = /var/run/mysqld/mysqld.pid
character_set_server = utf8mb4
collation_server = utf8mb4_general_ci
sql-mode = "NO_ENGINE_SUBSTITUTION"
slave-skip-errors = 1062

# SAFETY #
max_allowed_packet = 4M
max_connect_errors = 1000000
skip_name_resolve = 1
sysdate_is_now = 1
innodb_strict_mode = 1

# DATA STORAGE #
datadir = /var/lib/mysql

# BINARY LOGGING #
log_bin = /var/lib/mysql/log/mysql-bin
expire_logs_days = 1
sync_binlog = 1

# REPLICATION #
relay_log = /var/lib/mysql/mysqld-relay-bin
slave_net_timeout = 60
server-id = 21

# CACHES AND LIMITS #
back_log = 2048
tmp_table_size = 128M
max_heap_table_size = 256M
query_cache_type = 1
query_cache_size = 0
max_connections = 5000
thread_stack = 192K
thread_cache_size = 100
open_files_limit = 65535
table_definition_cache = 4096
table_open_cache = 4096
sort_buffer_size = 8M
read_buffer_size = 4M
wait_timeout = 28800

# INNODB #
innodb_buffer_pool_size = 45027M
innodb_flush_method = O_DIRECT
innodb_log_files_in_group = 2
innodb_log_file_size = 256M
innodb_flush_log_at_trx_commit = 0
innodb_file_per_table = 1
innodb_file_format = BARRACUDA

# LOGGING #
log-error = /var/log/mysql.log
slow_query_log = 1
slow_query_log_file = /var/lib/mysql/log/mysql-slow.log

[Christian (cw-y)]

Meanwhile we figured out that the problem was "flush tables" while running a query that takes a long time (20 sec).
It seems that when rotating binlogs, mysql also flushes tables and waits for all running queries to finish.

[Christian (cw-y)]

We think we narrowed it down to the file binlog.cc (we use gtid_mode = Off)

Method: MYSQL_BIN_LOG::purge_logs
Block:
 // Update gtid_state->lost_gtids
 if (!is_relay_log)
 {
   global_sid_lock->wrlock();
   error= init_gtid_sets(NULL,
                         const_cast<Gtid_set *>(gtid_state->get_lost_gtids()),
                         opt_master_verify_checksum,
                         false/*false=don't need lock*/,
                         NULL/*trx_parser*/, NULL/*gtid_partial_trx*/);
   global_sid_lock->unlock();
   if (error)
     goto err;
 }

should be:
…
 if (gtid_mode > 0 && !is_relay_log)
…

It looks like global_sid_lock causes the block.

[Shahriyar Rzayev (rzayev-sehriyar)]

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