Skip to content

Commit 739ac25

Browse files
author
Venkatesh Duggirala
committed
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. 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.
1 parent a142352 commit 739ac25

4 files changed

Lines changed: 89 additions & 12 deletions

File tree

‎mysql-test/suite/binlog/r/show_binlog_events_no_lock.result‎

Lines changed: 10 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,10 @@
1+
RESET MASTER;
2+
CREATE TABLE t1(i INT);
3+
DROP TABLE t1;
4+
SET DEBUG_SYNC = "wait_in_show_binlog_events_loop SIGNAL reached_for_loop WAIT_FOR go_ahead";
5+
SHOW BINLOG EVENTS;
6+
SET DEBUG_SYNC = "now WAIT_FOR reached_for_loop";
7+
CREATE TABLE t1(i INT);
8+
INSERT INTO t1 VALUES (12);
9+
DROP TABLE t1;
10+
SET DEBUG_SYNC = "now SIGNAL go_ahead";

‎mysql-test/suite/binlog/t/show_binlog_events_no_lock.test‎

Lines changed: 50 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,50 @@
1+
###########################################################################
2+
# BUG#20928790 SHOW BINLOG EVENTS COMPLETELY LOCKS DOWN WRITES TO BINLOG, #
3+
# HENCE TRANSACTIONS. #
4+
# #
5+
# Problem: While a `SHOW BINLOG EVENTS` is executing, any parallel #
6+
# transaction is blocked. #
7+
# #
8+
# Steps to reproduce: #
9+
# =================== #
10+
# 1) Execute 'show binlog events' on one connection and let it wait #
11+
# inside a loop that reads the events from the file using DEBUG_SYNC #
12+
# point #
13+
# 2) While the command is waiting, execute some transactions and see #
14+
# that they are not blocked. #
15+
# #
16+
###########################################################################
17+
--source include/have_debug_sync.inc
18+
--source include/have_binlog_format_statement.inc
19+
20+
# To make test to start with master-bin.000001
21+
RESET MASTER;
22+
# Run some sample tests to put it in master-bin.000001
23+
CREATE TABLE t1(i INT);
24+
DROP TABLE t1;
25+
26+
connect (con1,localhost,root,,);
27+
# Let show binlog events wait while it is reading events
28+
SET DEBUG_SYNC = "wait_in_show_binlog_events_loop SIGNAL reached_for_loop WAIT_FOR go_ahead";
29+
--send SHOW BINLOG EVENTS
30+
31+
--connection default
32+
# Make sure show binlog events execution reaches the point where we wanted to
33+
SET DEBUG_SYNC = "now WAIT_FOR reached_for_loop";
34+
35+
# Now execute some transactions and it should not be blocked
36+
CREATE TABLE t1(i INT);
37+
INSERT INTO t1 VALUES (12);
38+
DROP TABLE t1;
39+
40+
# Once above sample transactions are running fine, send signal to continue
41+
# 'show binlog events' command
42+
SET DEBUG_SYNC = "now SIGNAL go_ahead";
43+
44+
# Make sure show binlog events run successfully
45+
# 'show binlog events' output varies for different runs
46+
# (gtid, non-gtid, 5.6, 5.7). So lets disable the output
47+
--disable_result_log
48+
--connection con1
49+
--reap
50+
--enable_result_log

‎sql/binlog.cc‎

Lines changed: 27 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -2282,15 +2282,32 @@ bool show_binlog_events(THD *thd, MYSQL_BIN_LOG *binary_log)
22822282
if ((file=open_binlog_file(&log, linfo.log_file_name, &errmsg)) < 0)
22832283
goto err;
22842284

2285+
my_off_t end_pos;
2286+
/*
2287+
Acquire LOCK_log only for the duration to calculate the
2288+
log's end position. LOCK_log should be acquired even while
2289+
we are checking whether the log is active log or not.
2290+
*/
2291+
mysql_mutex_lock(log_lock);
2292+
if (binary_log->is_active(linfo.log_file_name))
2293+
{
2294+
LOG_INFO li;
2295+
binary_log->get_current_log(&li, false /*LOCK_log is already acquired*/);
2296+
end_pos= li.pos;
2297+
}
2298+
else
2299+
{
2300+
end_pos= my_b_filelength(&log);
2301+
}
2302+
mysql_mutex_unlock(log_lock);
2303+
22852304
/*
22862305
to account binlog event header size
22872306
*/
22882307
thd->variables.max_allowed_packet += MAX_LOG_EVENT_HEADER;
22892308

22902309
DEBUG_SYNC(thd, "after_show_binlog_event_found_file");
22912310

2292-
mysql_mutex_lock(log_lock);
2293-
22942311
/*
22952312
open_binlog_file() sought to position 4.
22962313
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)
23252342
description_event,
23262343
opt_master_verify_checksum)); )
23272344
{
2345+
DEBUG_SYNC(thd, "wait_in_show_binlog_events_loop");
23282346
if (ev->get_type_code() == FORMAT_DESCRIPTION_EVENT)
23292347
description_event->checksum_alg= ev->checksum_alg;
23302348

@@ -2333,25 +2351,22 @@ bool show_binlog_events(THD *thd, MYSQL_BIN_LOG *binary_log)
23332351
{
23342352
errmsg = "Net error";
23352353
delete ev;
2336-
mysql_mutex_unlock(log_lock);
23372354
goto err;
23382355
}
23392356

23402357
pos = my_b_tell(&log);
23412358
delete ev;
23422359

2343-
if (++event_count >= limit_end)
2360+
if (++event_count >= limit_end || pos >= end_pos)
23442361
break;
23452362
}
23462363

23472364
if (event_count < limit_end && log.error)
23482365
{
23492366
errmsg = "Wrong offset or I/O error";
2350-
mysql_mutex_unlock(log_lock);
23512367
goto err;
23522368
}
23532369

2354-
mysql_mutex_unlock(log_lock);
23552370
}
23562371
// Check that linfo is still on the function scope.
23572372
DEBUG_SYNC(thd, "after_show_binlog_events");
@@ -3501,18 +3516,20 @@ int MYSQL_BIN_LOG::add_log_to_index(uchar* log_name,
35013516
DBUG_RETURN(-1);
35023517
}
35033518

3504-
int MYSQL_BIN_LOG::get_current_log(LOG_INFO* linfo)
3519+
int MYSQL_BIN_LOG::get_current_log(LOG_INFO* linfo, bool need_lock_log/*true*/)
35053520
{
3506-
mysql_mutex_lock(&LOCK_log);
3521+
if (need_lock_log)
3522+
mysql_mutex_lock(&LOCK_log);
35073523
int ret = raw_get_current_log(linfo);
3508-
mysql_mutex_unlock(&LOCK_log);
3524+
if (need_lock_log)
3525+
mysql_mutex_unlock(&LOCK_log);
35093526
return ret;
35103527
}
35113528

35123529
int MYSQL_BIN_LOG::raw_get_current_log(LOG_INFO* linfo)
35133530
{
35143531
strmake(linfo->log_file_name, log_file_name, sizeof(linfo->log_file_name)-1);
3515-
linfo->pos = my_b_tell(&log_file);
3532+
linfo->pos = my_b_safe_tell(&log_file);
35163533
return 0;
35173534
}
35183535

‎sql/binlog.h‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
#ifndef BINLOG_H_INCLUDED
2-
/* Copyright (c) 2010, 2014, Oracle and/or its affiliates. All rights reserved.
2+
/* Copyright (c) 2010, 2015, Oracle and/or its affiliates. All rights reserved.
33
44
This program is free software; you can redistribute it and/or modify
55
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
663663
int find_log_pos(LOG_INFO* linfo, const char* log_name,
664664
bool need_lock_index);
665665
int find_next_log(LOG_INFO* linfo, bool need_lock_index);
666-
int get_current_log(LOG_INFO* linfo);
666+
int get_current_log(LOG_INFO* linfo, bool need_lock_log= true);
667667
int raw_get_current_log(LOG_INFO* linfo);
668668
uint next_file_id();
669669
inline char* get_index_fname() { return index_file_name;}

0 commit comments

Comments
 (0)