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).

mysql-test/suite/perfschema/r/relaylog.result

+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

mysql-test/suite/perfschema/t/relaylog.test

+# 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
+

sql/log.cc

@@ -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) 

sql/log.h

@@ -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);

sql/mysqld.cc

@@ -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},

sql/mysqld.h

@@ -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 */

sql/rpl_rli.cc

@@ -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",