Permalink
Browse files

BUG#20928790 SHOW BINLOG EVENTS COMPLETELY LOCKS DOWN WRITES TO BINLO…

…G, HENCE TRANSACTIONS.

Problem: While a `SHOW BINLOG EVENTS` is executing, any parallel transaction
is blocked.

Analysis:
========

In the good old days, replication was coded such that every access to the
binlog was protected by a mutex. So `Show binlog events` also acquires
LOCK_log mutex and loops through the file to print the events in order not
to get conflicts with any ongoing operations. While this operation is happening,
all binlog write operation which are trying to acquire LOCK_log mutex are blocked.
Hence all the parallel transactions are blocked.

When 'show binlog events' opens the file to read the events from it,
the file is locked and if there is parallel purge operation to delete
this file that operation will fail with a warning that "file 'xyz' was
not purged because it was being read by another thread". Hence
server does not require to acquire a lock while iterating through
the events in the file.

Fix:
====
Acquire LOCK_log only for the duration to calculate the log's end
position. LOCK_log should be acquired even while we are checking
whether the log is active log or not. Once 'end_pos' is calculated
for the given binary log, the events are displayed till that position.
Since we do not acquire LOCK_log (acquired only for less duration),
parallel transactions will not be blocked for large duration.
  • Loading branch information...
Venkatesh Duggirala
Venkatesh Duggirala committed Aug 18, 2015
1 parent a142352 commit 739ac25439176f309cd2132ce16fe49d918127c7
@@ -0,0 +1,10 @@
RESET MASTER;
CREATE TABLE t1(i INT);
DROP TABLE t1;
SET DEBUG_SYNC = "wait_in_show_binlog_events_loop SIGNAL reached_for_loop WAIT_FOR go_ahead";
SHOW BINLOG EVENTS;
SET DEBUG_SYNC = "now WAIT_FOR reached_for_loop";
CREATE TABLE t1(i INT);
INSERT INTO t1 VALUES (12);
DROP TABLE t1;
SET DEBUG_SYNC = "now SIGNAL go_ahead";
@@ -0,0 +1,50 @@
###########################################################################
# BUG#20928790 SHOW BINLOG EVENTS COMPLETELY LOCKS DOWN WRITES TO BINLOG, #
# HENCE TRANSACTIONS. #
# #
# Problem: While a `SHOW BINLOG EVENTS` is executing, any parallel #
# transaction is blocked. #
# #
# Steps to reproduce: #
# =================== #
# 1) Execute 'show binlog events' on one connection and let it wait #
# inside a loop that reads the events from the file using DEBUG_SYNC #
# point #
# 2) While the command is waiting, execute some transactions and see #
# that they are not blocked. #
# #
###########################################################################
--source include/have_debug_sync.inc
--source include/have_binlog_format_statement.inc
# To make test to start with master-bin.000001
RESET MASTER;
# Run some sample tests to put it in master-bin.000001
CREATE TABLE t1(i INT);
DROP TABLE t1;
connect (con1,localhost,root,,);
# Let show binlog events wait while it is reading events
SET DEBUG_SYNC = "wait_in_show_binlog_events_loop SIGNAL reached_for_loop WAIT_FOR go_ahead";
--send SHOW BINLOG EVENTS
--connection default
# Make sure show binlog events execution reaches the point where we wanted to
SET DEBUG_SYNC = "now WAIT_FOR reached_for_loop";
# Now execute some transactions and it should not be blocked
CREATE TABLE t1(i INT);
INSERT INTO t1 VALUES (12);
DROP TABLE t1;
# Once above sample transactions are running fine, send signal to continue
# 'show binlog events' command
SET DEBUG_SYNC = "now SIGNAL go_ahead";
# Make sure show binlog events run successfully
# 'show binlog events' output varies for different runs
# (gtid, non-gtid, 5.6, 5.7). So lets disable the output
--disable_result_log
--connection con1
--reap
--enable_result_log
View
@@ -2282,15 +2282,32 @@ bool show_binlog_events(THD *thd, MYSQL_BIN_LOG *binary_log)
if ((file=open_binlog_file(&log, linfo.log_file_name, &errmsg)) < 0)
goto err;
my_off_t end_pos;
/*
Acquire LOCK_log only for the duration to calculate the
log's end position. LOCK_log should be acquired even while
we are checking whether the log is active log or not.
*/
mysql_mutex_lock(log_lock);
if (binary_log->is_active(linfo.log_file_name))
{
LOG_INFO li;
binary_log->get_current_log(&li, false /*LOCK_log is already acquired*/);
end_pos= li.pos;
}
else
{
end_pos= my_b_filelength(&log);
}
mysql_mutex_unlock(log_lock);
/*
to account binlog event header size
*/
thd->variables.max_allowed_packet += MAX_LOG_EVENT_HEADER;
DEBUG_SYNC(thd, "after_show_binlog_event_found_file");
mysql_mutex_lock(log_lock);
/*
open_binlog_file() sought to position 4.
Read the first event in case it's a Format_description_log_event, to
@@ -2325,6 +2342,7 @@ bool show_binlog_events(THD *thd, MYSQL_BIN_LOG *binary_log)
description_event,
opt_master_verify_checksum)); )
{
DEBUG_SYNC(thd, "wait_in_show_binlog_events_loop");
if (ev->get_type_code() == FORMAT_DESCRIPTION_EVENT)
description_event->checksum_alg= ev->checksum_alg;
@@ -2333,25 +2351,22 @@ bool show_binlog_events(THD *thd, MYSQL_BIN_LOG *binary_log)
{
errmsg = "Net error";
delete ev;
mysql_mutex_unlock(log_lock);
goto err;
}
pos = my_b_tell(&log);
delete ev;
if (++event_count >= limit_end)
if (++event_count >= limit_end || pos >= end_pos)
break;
}
if (event_count < limit_end && log.error)
{
errmsg = "Wrong offset or I/O error";
mysql_mutex_unlock(log_lock);
goto err;
}
mysql_mutex_unlock(log_lock);
}
// Check that linfo is still on the function scope.
DEBUG_SYNC(thd, "after_show_binlog_events");
@@ -3501,18 +3516,20 @@ int MYSQL_BIN_LOG::add_log_to_index(uchar* log_name,
DBUG_RETURN(-1);
}
int MYSQL_BIN_LOG::get_current_log(LOG_INFO* linfo)
int MYSQL_BIN_LOG::get_current_log(LOG_INFO* linfo, bool need_lock_log/*true*/)
{
mysql_mutex_lock(&LOCK_log);
if (need_lock_log)
mysql_mutex_lock(&LOCK_log);
int ret = raw_get_current_log(linfo);
mysql_mutex_unlock(&LOCK_log);
if (need_lock_log)
mysql_mutex_unlock(&LOCK_log);
return ret;
}
int MYSQL_BIN_LOG::raw_get_current_log(LOG_INFO* linfo)
{
strmake(linfo->log_file_name, log_file_name, sizeof(linfo->log_file_name)-1);
linfo->pos = my_b_tell(&log_file);
linfo->pos = my_b_safe_tell(&log_file);
return 0;
}
View
@@ -1,5 +1,5 @@
#ifndef BINLOG_H_INCLUDED
/* Copyright (c) 2010, 2014, Oracle and/or its affiliates. All rights reserved.
/* Copyright (c) 2010, 2015, Oracle and/or its affiliates. All rights reserved.
This program is free software; you can redistribute it and/or modify
it under the terms of the GNU General Public License as published by
@@ -663,7 +663,7 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
int find_log_pos(LOG_INFO* linfo, const char* log_name,
bool need_lock_index);
int find_next_log(LOG_INFO* linfo, bool need_lock_index);
int get_current_log(LOG_INFO* linfo);
int get_current_log(LOG_INFO* linfo, bool need_lock_log= true);
int raw_get_current_log(LOG_INFO* linfo);
uint next_file_id();
inline char* get_index_fname() { return index_file_name;}

0 comments on commit 739ac25

Please sign in to comment.