Commit 5ee90018 authored by Marc Alff's avatar Marc Alff

Bug#11766528 PERFORMANCE_SCHEMA TRACKS BOTH BINARY AND RELAY LOGS IN THE SAME EVENTS

Before this fix, all the performance schema instrumentation for both the binary log
and the relay log would use the following instruments:
- wait/io/file/sql/binlog
- wait/io/file/sql/binlog_index
- wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index
- wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond

This instrumentation is too general and can be more specific.

With this fix, the binlog instrumentation is identical,
and the relay log instrumentation is changed to:
- wait/io/file/sql/relaylog
- wait/io/file/sql/relaylog_index
- wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_index
- wait/synch/cond/sql/MYSQL_RELAY_LOG::update_cond

With this change, the performance instrumentation for the binary log and the relay log,
which share the same structure but have different uses, is more detailed.
This is especially important for hosts in the middle of a replication chain,
that are both masters (binlog) and slaves (relaylog).
parent 69b82937
include/master-slave.inc
[connection master]
drop table if exists test.t1;
reset master;
create table test.t1(a int);
drop table test.t1;
show binlog events from <binlog_start>;
Log_name Pos Event_type Server_id End_log_pos Info
slave-bin.000001 # Query # # use `test`; create table test.t1(a int)
slave-bin.000001 # Query # # use `test`; DROP TABLE `t1` /* generated by server */
"============ Performance schema on master ============"
select * from performance_schema.file_summary_by_instance
where file_name like "%master-%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
[DATADIR]master-bin.000001 wait/io/file/sql/binlog 6 4 221 329
[DATADIR]master-bin.index wait/io/file/sql/binlog_index 0 2 0 40
select * from performance_schema.file_summary_by_instance
where file_name like "%slave-%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
select * from performance_schema.file_summary_by_instance
where event_name like "%binlog%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
[DATADIR]master-bin.000001 wait/io/file/sql/binlog 6 4 221 329
[DATADIR]master-bin.index wait/io/file/sql/binlog_index 0 2 0 40
select * from performance_schema.file_summary_by_event_name
where event_name like "%binlog%" order by event_name;
EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
wait/io/file/sql/binlog 6 4 221 329
wait/io/file/sql/binlog_index 0 2 0 40
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_BIN_LOG%" order by event_name;
event_name count_star
wait/synch/cond/sql/MYSQL_BIN_LOG::COND_prep_xids 0
wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond 1
wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index 3
wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_prep_xids 0
select * from performance_schema.file_summary_by_instance
where event_name like "%relaylog%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
select * from performance_schema.file_summary_by_event_name
where event_name like "%relaylog%" order by event_name;
EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
wait/io/file/sql/relaylog 0 0 0 0
wait/io/file/sql/relaylog_index 0 0 0 0
select * from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_RELAY_LOG%" order by event_name;
EVENT_NAME COUNT_STAR SUM_TIMER_WAIT MIN_TIMER_WAIT AVG_TIMER_WAIT MAX_TIMER_WAIT
wait/synch/cond/sql/MYSQL_RELAY_LOG::update_cond 0 0 0 0 0
wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_index 0 0 0 0 0
"============ Performance schema on slave ============"
select * from performance_schema.file_summary_by_instance
where file_name like "%master-%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
select * from performance_schema.file_summary_by_instance
where file_name like "%slave-%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
[DATADIR]slave-bin.000001 wait/io/file/sql/binlog 3 8 602 631
[DATADIR]slave-bin.index wait/io/file/sql/binlog_index 0 3 0 57
[DATADIR]slave-relay-bin.000001 wait/io/file/sql/relaylog 4 3 370 263
[DATADIR]slave-relay-bin.000002 wait/io/file/sql/relaylog 2 4 368 368
[DATADIR]slave-relay-bin.index wait/io/file/sql/relaylog_index 2 4 50 125
select * from performance_schema.file_summary_by_instance
where event_name like "%binlog%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
[DATADIR]slave-bin.000001 wait/io/file/sql/binlog 3 8 602 631
[DATADIR]slave-bin.index wait/io/file/sql/binlog_index 0 3 0 57
select * from performance_schema.file_summary_by_event_name
where event_name like "%binlog%" order by event_name;
EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
wait/io/file/sql/binlog 3 8 602 631
wait/io/file/sql/binlog_index 0 3 0 57
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_BIN_LOG%" order by event_name;
event_name count_star
wait/synch/cond/sql/MYSQL_BIN_LOG::COND_prep_xids 0
wait/synch/cond/sql/MYSQL_BIN_LOG::update_cond 0
wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index 5
wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_prep_xids 0
select * from performance_schema.file_summary_by_instance
where event_name like "%relaylog%" order by file_name;
FILE_NAME EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
[DATADIR]slave-relay-bin.000001 wait/io/file/sql/relaylog 4 3 370 263
[DATADIR]slave-relay-bin.000002 wait/io/file/sql/relaylog 2 4 368 368
[DATADIR]slave-relay-bin.index wait/io/file/sql/relaylog_index 2 4 50 125
select * from performance_schema.file_summary_by_event_name
where event_name like "%relaylog%" order by event_name;
EVENT_NAME COUNT_READ COUNT_WRITE SUM_NUMBER_OF_BYTES_READ SUM_NUMBER_OF_BYTES_WRITE
wait/io/file/sql/relaylog 6 7 738 631
wait/io/file/sql/relaylog_index 2 4 50 125
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_RELAY_LOG%" order by event_name;
event_name count_star
wait/synch/cond/sql/MYSQL_RELAY_LOG::update_cond 2
wait/synch/mutex/sql/MYSQL_RELAY_LOG::LOCK_index 12
include/stop_slave.inc
# Copyright (c) 2011, 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
# the Free Software Foundation; version 2 of the License.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program; if not, write to the Free Software Foundation,
# 51 Franklin Street, Suite 500, Boston, MA 02110-1335 USA
# Tests for PERFORMANCE_SCHEMA
--source include/have_log_bin.inc
--source include/not_embedded.inc
--source include/have_perfschema.inc
--source include/master-slave.inc
--disable_warnings
drop table if exists test.t1;
--sync_slave_with_master
reset master;
--enable_warnings
create table test.t1(a int);
drop table test.t1;
--source include/show_binlog_events.inc
connection master;
-- echo "============ Performance schema on master ============"
let $MYSQLD_DATADIR= `SELECT @@datadir`;
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where file_name like "%master-%" order by file_name;
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where file_name like "%slave-%" order by file_name;
# Expect a master binlog + binlog_index
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where event_name like "%binlog%" order by file_name;
select * from performance_schema.file_summary_by_event_name
where event_name like "%binlog%" order by event_name;
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_BIN_LOG%" order by event_name;
# Expect no slave relay log.
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where event_name like "%relaylog%" order by file_name;
select * from performance_schema.file_summary_by_event_name
where event_name like "%relaylog%" order by event_name;
select * from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_RELAY_LOG%" order by event_name;
sync_slave_with_master;
-- echo "============ Performance schema on slave ============"
let $MYSQLD_DATADIR= `SELECT @@datadir`;
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where file_name like "%master-%" order by file_name;
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where file_name like "%slave-%" order by file_name;
# Expect a slave binlog + binlog_index
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where event_name like "%binlog%" order by file_name;
select * from performance_schema.file_summary_by_event_name
where event_name like "%binlog%" order by event_name;
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_BIN_LOG%" order by event_name;
# Expect a slave relay log.
--replace_result $MYSQLD_DATADIR [DATADIR]
select * from performance_schema.file_summary_by_instance
where event_name like "%relaylog%" order by file_name;
select * from performance_schema.file_summary_by_event_name
where event_name like "%relaylog%" order by event_name;
select event_name, count_star
from performance_schema.events_waits_summary_global_by_event_name
where event_name like "%MYSQL_RELAY_LOG%" order by event_name;
--source include/stop_slave.inc
......@@ -2861,11 +2861,9 @@ void MYSQL_BIN_LOG::init(bool no_auto_events_arg, ulong max_size_arg)
void MYSQL_BIN_LOG::init_pthread_objects()
{
DBUG_ASSERT(inited == 0);
inited= 1;
mysql_mutex_init(key_LOG_LOCK_log, &LOCK_log, MY_MUTEX_INIT_SLOW);
mysql_mutex_init(key_BINLOG_LOCK_index, &LOCK_index, MY_MUTEX_INIT_SLOW);
mysql_cond_init(key_BINLOG_update_cond, &update_cond, 0);
MYSQL_LOG::init_pthread_objects();
mysql_mutex_init(m_key_LOCK_index, &LOCK_index, MY_MUTEX_INIT_SLOW);
mysql_cond_init(m_key_update_cond, &update_cond, 0);
}
......@@ -2888,7 +2886,7 @@ bool MYSQL_BIN_LOG::open_index_file(const char *index_file_name_arg,
}
fn_format(index_file_name, index_file_name_arg, mysql_data_home,
".index", opt);
if ((index_file_nr= mysql_file_open(key_file_binlog_index,
if ((index_file_nr= mysql_file_open(m_key_file_log_index,
index_file_name,
O_RDWR | O_CREAT | O_BINARY,
MYF(MY_WME))) < 0 ||
......@@ -3004,7 +3002,7 @@ bool MYSQL_BIN_LOG::open(const char *log_name,
/* open the main log file */
if (MYSQL_LOG::open(
#ifdef HAVE_PSI_INTERFACE
key_file_binlog,
m_key_file_log,
#endif
log_name, log_type_arg, new_name, io_cache_type_arg))
{
......@@ -3874,7 +3872,7 @@ int MYSQL_BIN_LOG::purge_index_entry(THD *thd, ulonglong *decrease_log_space,
/* Get rid of the trailing '\n' */
log_info.log_file_name[length-1]= 0;
if (!mysql_file_stat(key_file_binlog, log_info.log_file_name, &s, MYF(0)))
if (!mysql_file_stat(m_key_file_log, log_info.log_file_name, &s, MYF(0)))
{
if (my_errno == ENOENT)
{
......@@ -4049,7 +4047,7 @@ int MYSQL_BIN_LOG::purge_logs_before_date(time_t purge_time)
!is_active(log_info.log_file_name) &&
!log_in_use(log_info.log_file_name))
{
if (!mysql_file_stat(key_file_binlog,
if (!mysql_file_stat(m_key_file_log,
log_info.log_file_name, &stat_area, MYF(0)))
{
if (my_errno == ENOENT)
......
......@@ -274,6 +274,16 @@ class MYSQL_QUERY_LOG: public MYSQL_LOG
class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
{
private:
#ifdef HAVE_PSI_INTERFACE
/** The instrumentation key to use for @ LOCK_index. */
PSI_mutex_key m_key_LOCK_index;
/** The instrumentation key to use for @ update_cond. */
PSI_cond_key m_key_update_cond;
/** The instrumentation key to use for opening the log file. */
PSI_file_key m_key_file_log;
/** The instrumentation key to use for opening the log index file. */
PSI_file_key m_key_file_log_index;
#endif
/* LOCK_log and LOCK_index are inited by init_pthread_objects() */
mysql_mutex_t LOCK_index;
mysql_mutex_t LOCK_prep_xids;
......@@ -362,6 +372,19 @@ class MYSQL_BIN_LOG: public TC_LOG, private MYSQL_LOG
on exit() - but only during the correct shutdown process
*/
#ifdef HAVE_PSI_INTERFACE
void set_psi_keys(PSI_mutex_key key_LOCK_index,
PSI_cond_key key_update_cond,
PSI_file_key key_file_log,
PSI_file_key key_file_log_index)
{
m_key_LOCK_index= key_LOCK_index;
m_key_update_cond= key_update_cond;
m_key_file_log= key_file_log;
m_key_file_log_index= key_file_log_index;
}
#endif
int open(const char *opt_name);
void close();
int log_xid(THD *thd, my_xid xid);
......
......@@ -3122,6 +3122,18 @@ static int init_common_variables()
*/
global_system_variables.time_zone= my_tz_SYSTEM;
#ifdef HAVE_PSI_INTERFACE
/*
Complete the mysql_bin_log initialization.
Instrumentation keys are known only after the performance schema initialization,
and can not be set in the MYSQL_BIN_LOG constructor (called before main()).
*/
mysql_bin_log.set_psi_keys(key_BINLOG_LOCK_index,
key_BINLOG_update_cond,
key_file_binlog,
key_file_binlog_index);
#endif
/*
Init mutexes for the global MYSQL_BIN_LOG objects.
As safe_mutex depends on what MY_INIT() does, we can't init the mutexes of
......@@ -7690,6 +7702,7 @@ PSI_mutex_key key_BINLOG_LOCK_index, key_BINLOG_LOCK_prep_xids,
key_structure_guard_mutex, key_TABLE_SHARE_LOCK_ha_data,
key_LOCK_error_messages, key_LOG_INFO_lock, key_LOCK_thread_count,
key_PARTITION_LOCK_auto_inc;
PSI_mutex_key key_RELAYLOG_LOCK_index;
static PSI_mutex_info all_server_mutexes[]=
{
......@@ -7706,6 +7719,7 @@ static PSI_mutex_info all_server_mutexes[]=
{ &key_BINLOG_LOCK_index, "MYSQL_BIN_LOG::LOCK_index", 0},
{ &key_BINLOG_LOCK_prep_xids, "MYSQL_BIN_LOG::LOCK_prep_xids", 0},
{ &key_RELAYLOG_LOCK_index, "MYSQL_RELAY_LOG::LOCK_index", 0},
{ &key_delayed_insert_mutex, "Delayed_insert::mutex", 0},
{ &key_hash_filo_lock, "hash_filo::lock", 0},
{ &key_LOCK_active_mi, "LOCK_active_mi", PSI_FLAG_GLOBAL},
......@@ -7773,6 +7787,7 @@ PSI_cond_key key_BINLOG_COND_prep_xids, key_BINLOG_update_cond,
key_relay_log_info_start_cond, key_relay_log_info_stop_cond,
key_TABLE_SHARE_cond, key_user_level_lock_cond,
key_COND_thread_count, key_COND_thread_cache, key_COND_flush_thread_cache;
PSI_cond_key key_RELAYLOG_update_cond;
static PSI_cond_info all_server_conds[]=
{
......@@ -7786,6 +7801,7 @@ static PSI_cond_info all_server_conds[]=
#endif /* HAVE_MMAP */
{ &key_BINLOG_COND_prep_xids, "MYSQL_BIN_LOG::COND_prep_xids", 0},
{ &key_BINLOG_update_cond, "MYSQL_BIN_LOG::update_cond", 0},
{ &key_RELAYLOG_update_cond, "MYSQL_RELAY_LOG::update_cond", 0},
{ &key_COND_cache_status_changed, "Query_cache::COND_cache_status_changed", 0},
{ &key_COND_manager, "COND_manager", PSI_FLAG_GLOBAL},
{ &key_COND_rpl_status, "COND_rpl_status", PSI_FLAG_GLOBAL},
......@@ -7849,6 +7865,7 @@ PSI_file_key key_file_binlog, key_file_binlog_index, key_file_casetest,
key_file_pid, key_file_relay_log_info, key_file_send_file, key_file_tclog,
key_file_trg, key_file_trn, key_file_init;
PSI_file_key key_file_query_log, key_file_slow_log;
PSI_file_key key_file_relaylog, key_file_relaylog_index;
static PSI_file_info all_server_files[]=
{
......@@ -7857,6 +7874,8 @@ static PSI_file_info all_server_files[]=
#endif /* HAVE_MMAP */
{ &key_file_binlog, "binlog", 0},
{ &key_file_binlog_index, "binlog_index", 0},
{ &key_file_relaylog, "relaylog", 0},
{ &key_file_relaylog_index, "relaylog_index", 0},
{ &key_file_casetest, "casetest", 0},
{ &key_file_dbopt, "dbopt", 0},
{ &key_file_des_key_file, "des_key_file", 0},
......
......@@ -241,6 +241,7 @@ extern PSI_mutex_key key_BINLOG_LOCK_index, key_BINLOG_LOCK_prep_xids,
key_relay_log_info_log_space_lock, key_relay_log_info_run_lock,
key_structure_guard_mutex, key_TABLE_SHARE_LOCK_ha_data,
key_LOCK_error_messages, key_LOCK_thread_count, key_PARTITION_LOCK_auto_inc;
extern PSI_mutex_key key_RELAYLOG_LOCK_index;
extern PSI_rwlock_key key_rwlock_LOCK_grant, key_rwlock_LOCK_logger,
key_rwlock_LOCK_sys_init_connect, key_rwlock_LOCK_sys_init_slave,
......@@ -260,6 +261,7 @@ extern PSI_cond_key key_BINLOG_COND_prep_xids, key_BINLOG_update_cond,
key_relay_log_info_start_cond, key_relay_log_info_stop_cond,
key_TABLE_SHARE_cond, key_user_level_lock_cond,
key_COND_thread_count, key_COND_thread_cache, key_COND_flush_thread_cache;
extern PSI_cond_key key_RELAYLOG_update_cond;
extern PSI_thread_key key_thread_bootstrap, key_thread_delayed_insert,
key_thread_handle_manager, key_thread_kill_server, key_thread_main,
......@@ -277,6 +279,7 @@ extern PSI_file_key key_file_binlog, key_file_binlog_index, key_file_casetest,
key_file_pid, key_file_relay_log_info, key_file_send_file, key_file_tclog,
key_file_trg, key_file_trn, key_file_init;
extern PSI_file_key key_file_query_log, key_file_slow_log;
extern PSI_file_key key_file_relaylog, key_file_relaylog_index;
void init_server_psi_keys();
#endif /* HAVE_PSI_INTERFACE */
......
......@@ -54,6 +54,13 @@ Relay_log_info::Relay_log_info(bool is_slave_recovery)
{
DBUG_ENTER("Relay_log_info::Relay_log_info");
#ifdef HAVE_PSI_INTERFACE
relay_log.set_psi_keys(key_RELAYLOG_LOCK_index,
key_RELAYLOG_update_cond,
key_file_relaylog,
key_file_relaylog_index);
#endif
group_relay_log_name[0]= event_relay_log_name[0]=
group_master_log_name[0]= 0;
until_log_name[0]= ign_master_log_name_end[0]= 0;
......@@ -356,7 +363,7 @@ static inline int add_relay_log(Relay_log_info* rli,LOG_INFO* linfo)
{
MY_STAT s;
DBUG_ENTER("add_relay_log");
if (!mysql_file_stat(key_file_binlog,
if (!mysql_file_stat(key_file_relaylog,
linfo->log_file_name, &s, MYF(0)))
{
sql_print_error("log %s listed in the index, but failed to stat",
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment