Bug#58052 Binary log IO not being accounted for properly

Before this fix, file io for the binary log file was not accounted properly,
and showed no io at all.

This bug was due to the following issues:

1) file io for the binlog was instrumented:
- sometime as "wait/io/file/sql/binlog"
- sometime as "wait/io/file/sql/MYSQL_LOG"
leading to inconsistent event_names.

2) the binlog file itself was using an IO_CACHE,
but the IO_CACHE implementation in mysys/mf_iocache.c was
not instrumented to make performance schema calls to record file io.

3) The "wait/io/file/sql/MYSQL_LOG" instrumentation was used
for several log files, such as:
- the binary log
- the slow log
- the query log
which caused file io in these different log files to be accounted
against the same instrument.
The instrumentation needs to have a finer grain and report io
in different event_names, because each file really serves a different purpose.

With this fix:
- the IO_CACHE implementation is now instrumented
- the "wait/io/file/sql/MYSQL_LOG" instrument has been removed
- binlog io is now always instrumented with "wait/io/file/sql/binlog"
- the slow log is instrumented with a new name, "wait/io/file/sql/slow_log"
- the query log is instrumented with a new name, "wait/io/file/sql/query_log"

5 files changed, 69 insertions, 37 deletions

diff --git a/mysys/mf_iocache.c b/mysys/mf_iocache.c
index 173b678cdd1..575581712d4 100644
--- a/mysys/mf_iocache.c
+++ b/mysys/mf_iocache.c
@@ -173,7 +173,7 @@ int init_io_cache(IO_CACHE *info, File file, size_t cachesize,
 
   if (file >= 0)
   {
-    pos= my_tell(file, MYF(0));
+    pos= mysql_file_tell(file, MYF(0));
     if ((pos == (my_off_t) -1) && (my_errno == ESPIPE))
     {
       /*
@@ -205,7 +205,7 @@ int init_io_cache(IO_CACHE *info, File file, size_t cachesize,
     if (!(cache_myflags & MY_DONT_CHECK_FILESIZE))
     {
       /* Calculate end of file to avoid allocating oversized buffers */
-      end_of_file=my_seek(file,0L,MY_SEEK_END,MYF(0));
+      end_of_file= mysql_file_seek(file, 0L, MY_SEEK_END, MYF(0));
       /* Need to reset seek_not_done now that we just did a seek. */
       info->seek_not_done= end_of_file == seek_offset ? 0 : 1;
       if (end_of_file < seek_offset)
@@ -485,7 +485,7 @@ int _my_b_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
   */
   if (info->seek_not_done)
   {
-    if ((my_seek(info->file,pos_in_file,MY_SEEK_SET,MYF(0)) 
+    if ((mysql_file_seek(info->file, pos_in_file, MY_SEEK_SET, MYF(0)) 
         != MY_FILEPOS_ERROR))
     {
       /* No error, reset seek_not_done flag. */
@@ -529,7 +529,7 @@ int _my_b_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
       end aligned with a block.
     */
     length=(Count & (size_t) ~(IO_SIZE-1))-diff_length;
-    if ((read_length= my_read(info->file,Buffer, length, info->myflags))
+    if ((read_length= mysql_file_read(info->file,Buffer, length, info->myflags))
 	!= length)
     {
       /*
@@ -572,7 +572,7 @@ int _my_b_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
     }
     length=0;				/* Didn't read any chars */
   }
-  else if ((length= my_read(info->file,info->buffer, max_length,
+  else if ((length= mysql_file_read(info->file,info->buffer, max_length,
                             info->myflags)) < Count ||
 	   length == (size_t) -1)
   {
@@ -1056,7 +1056,7 @@ int _my_b_read_r(register IO_CACHE *cache, uchar *Buffer, size_t Count)
         */
         if (cache->seek_not_done)
         {
-          if (my_seek(cache->file, pos_in_file, MY_SEEK_SET, MYF(0))
+          if (mysql_file_seek(cache->file, pos_in_file, MY_SEEK_SET, MYF(0))
               == MY_FILEPOS_ERROR)
           {
             cache->error= -1;
@@ -1064,7 +1064,7 @@ int _my_b_read_r(register IO_CACHE *cache, uchar *Buffer, size_t Count)
             DBUG_RETURN(1);
           }
         }
-        len= my_read(cache->file, cache->buffer, length, cache->myflags);
+        len= mysql_file_read(cache->file, cache->buffer, length, cache->myflags);
       }
       DBUG_PRINT("io_cache_share", ("read %lu bytes", (ulong) len));
 
@@ -1203,7 +1203,7 @@ int _my_b_seq_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
     With read-append cache we must always do a seek before we read,
     because the write could have moved the file pointer astray
   */
-  if (my_seek(info->file,pos_in_file,MY_SEEK_SET,MYF(0)) == MY_FILEPOS_ERROR)
+  if (mysql_file_seek(info->file, pos_in_file, MY_SEEK_SET, MYF(0)) == MY_FILEPOS_ERROR)
   {
    info->error= -1;
    unlock_append_buffer(info);
@@ -1220,8 +1220,8 @@ int _my_b_seq_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
     size_t read_length;
 
     length=(Count & (size_t) ~(IO_SIZE-1))-diff_length;
-    if ((read_length= my_read(info->file,Buffer, length,
-                              info->myflags)) == (size_t) -1)
+    if ((read_length= mysql_file_read(info->file,Buffer, length,
+                                      info->myflags)) == (size_t) -1)
     {
       info->error= -1;
       unlock_append_buffer(info);
@@ -1254,7 +1254,7 @@ int _my_b_seq_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
   }
   else
   {
-    length= my_read(info->file,info->buffer, max_length, info->myflags);
+    length= mysql_file_read(info->file,info->buffer, max_length, info->myflags);
     if (length == (size_t) -1)
     {
       info->error= -1;
@@ -1431,7 +1431,7 @@ int _my_b_async_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
       return 1;
     }
     
-    if (my_seek(info->file,next_pos_in_file,MY_SEEK_SET,MYF(0))
+    if (mysql_file_seek(info->file, next_pos_in_file, MY_SEEK_SET, MYF(0))
         == MY_FILEPOS_ERROR)
     {
       info->error= -1;
@@ -1441,8 +1441,8 @@ int _my_b_async_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
     read_length=IO_SIZE*2- (size_t) (next_pos_in_file & (IO_SIZE-1));
     if (Count < read_length)
     {					/* Small block, read to cache */
-      if ((read_length=my_read(info->file,info->request_pos,
-			       read_length, info->myflags)) == (size_t) -1)
+      if ((read_length=mysql_file_read(info->file,info->request_pos,
+			               read_length, info->myflags)) == (size_t) -1)
         return info->error= -1;
       use_length=min(Count,read_length);
       memcpy(Buffer,info->request_pos,(size_t) use_length);
@@ -1462,7 +1462,7 @@ int _my_b_async_read(register IO_CACHE *info, uchar *Buffer, size_t Count)
     }
     else
     {						/* Big block, don't cache it */
-      if ((read_length= my_read(info->file,Buffer, Count,info->myflags))
+      if ((read_length= mysql_file_read(info->file, Buffer, Count,info->myflags))
 	  != Count)
       {
 	info->error= read_length == (size_t) -1 ? -1 : read_length+left_length;
@@ -1569,14 +1569,14 @@ int _my_b_write(register IO_CACHE *info, const uchar *Buffer, size_t Count)
         "seek_not_done" to indicate this to other functions operating
         on the IO_CACHE.
       */
-      if (my_seek(info->file,info->pos_in_file,MY_SEEK_SET,MYF(0)))
+      if (mysql_file_seek(info->file, info->pos_in_file, MY_SEEK_SET, MYF(0)))
       {
         info->error= -1;
         return (1);
       }
       info->seek_not_done=0;
     }
-    if (my_write(info->file, Buffer, length, info->myflags | MY_NABP))
+    if (mysql_file_write(info->file, Buffer, length, info->myflags | MY_NABP))
       return info->error= -1;
 
 #ifdef THREAD
@@ -1639,7 +1639,7 @@ int my_b_append(register IO_CACHE *info, const uchar *Buffer, size_t Count)
   if (Count >= IO_SIZE)
   {					/* Fill first intern buffer */
     length=Count & (size_t) ~(IO_SIZE-1);
-    if (my_write(info->file,Buffer, length, info->myflags | MY_NABP))
+    if (mysql_file_write(info->file,Buffer, length, info->myflags | MY_NABP))
     {
       unlock_append_buffer(info);
       return info->error= -1;
@@ -1695,11 +1695,11 @@ int my_block_write(register IO_CACHE *info, const uchar *Buffer, size_t Count,
   {
     /* Of no overlap, write everything without buffering */
     if (pos + Count <= info->pos_in_file)
-      return my_pwrite(info->file, Buffer, Count, pos,
-		       info->myflags | MY_NABP);
+      return mysql_file_pwrite(info->file, Buffer, Count, pos,
+		               info->myflags | MY_NABP);
     /* Write the part of the block that is before buffer */
     length= (uint) (info->pos_in_file - pos);
-    if (my_pwrite(info->file, Buffer, length, pos, info->myflags | MY_NABP))
+    if (mysql_file_pwrite(info->file, Buffer, length, pos, info->myflags | MY_NABP))
       info->error= error= -1;
     Buffer+=length;
     pos+=  length;
@@ -1789,7 +1789,7 @@ int my_b_flush_io_cache(IO_CACHE *info,
       */
       if (!append_cache && info->seek_not_done)
       {					/* File touched, do seek */
-	if (my_seek(info->file,pos_in_file,MY_SEEK_SET,MYF(0)) ==
+	if (mysql_file_seek(info->file, pos_in_file, MY_SEEK_SET, MYF(0)) ==
 	    MY_FILEPOS_ERROR)
 	{
 	  UNLOCK_APPEND_BUFFER;
@@ -1803,7 +1803,7 @@ int my_b_flush_io_cache(IO_CACHE *info,
       info->write_end= (info->write_buffer+info->buffer_length-
 			((pos_in_file+length) & (IO_SIZE-1)));
 
-      if (my_write(info->file,info->write_buffer,length,
+      if (mysql_file_write(info->file,info->write_buffer,length,
 		   info->myflags | MY_NABP))
 	info->error= -1;
       else
@@ -1815,7 +1815,7 @@ int my_b_flush_io_cache(IO_CACHE *info,
       else
       {
 	info->end_of_file+=(info->write_pos-info->append_read_pos);
-	DBUG_ASSERT(info->end_of_file == my_tell(info->file,MYF(0)));
+	DBUG_ASSERT(info->end_of_file == mysql_file_tell(info->file, MYF(0)));
       }
 
       info->append_read_pos=info->write_pos=info->write_buffer;
diff --git a/sql/log.cc b/sql/log.cc
index ae0cb813742..bfc5018b556 100644
--- a/sql/log.cc
+++ b/sql/log.cc
@@ -2177,7 +2177,11 @@ bool MYSQL_LOG::init_and_set_log_file_name(const char *log_name,
     1   error
 */
 
-bool MYSQL_LOG::open(const char *log_name, enum_log_type log_type_arg,
+bool MYSQL_LOG::open(
+#ifdef HAVE_PSI_INTERFACE
+                     PSI_file_key log_file_key,
+#endif
+                     const char *log_name, enum_log_type log_type_arg,
                      const char *new_name, enum cache_type io_cache_type_arg)
 {
   char buff[FN_REFLEN];
@@ -2205,7 +2209,12 @@ bool MYSQL_LOG::open(const char *log_name, enum_log_type log_type_arg,
 
   db[0]= 0;
 
-  if ((file= mysql_file_open(key_file_MYSQL_LOG,
+#ifdef HAVE_PSI_INTERFACE
+  /* Keep the key for reopen */
+  m_log_file_key= log_file_key;
+#endif
+
+  if ((file= mysql_file_open(log_file_key,
                              log_file_name, open_flags,
                              MYF(MY_WME | ME_WAITTANG))) < 0 ||
       init_io_cache(&log_file, file, IO_SIZE, io_cache_type,
@@ -2389,7 +2398,11 @@ void MYSQL_QUERY_LOG::reopen_file()
      Note that at this point, log_state != LOG_CLOSED (important for is_open()).
   */
 
-  open(save_name, log_type, 0, io_cache_type);
+  open(
+#ifdef HAVE_PSI_INTERFACE
+       m_log_file_key,
+#endif
+       save_name, log_type, 0, io_cache_type);
   my_free(save_name);
 
   mysql_mutex_unlock(&LOCK_log);
@@ -2855,8 +2868,8 @@ bool MYSQL_BIN_LOG::open(const char *log_name,
   write_error= 0;
 
   /* open the main log file */
-  if (MYSQL_LOG::open(log_name, log_type_arg, new_name,
-                      io_cache_type_arg))
+  if (MYSQL_LOG::open(key_file_binlog,
+                      log_name, log_type_arg, new_name, io_cache_type_arg))
   {
 #ifdef HAVE_REPLICATION
     close_purge_index_file();
diff --git a/sql/log.h b/sql/log.h
index 89b3594cd1e..d824d3afa26 100644
--- a/sql/log.h
+++ b/sql/log.h
@@ -196,7 +196,11 @@ public:
   MYSQL_LOG();
   void init_pthread_objects();
   void cleanup();
-  bool open(const char *log_name,
+  bool open(
+#ifdef HAVE_PSI_INTERFACE
+            PSI_file_key log_file_key,
+#endif
+            const char *log_name,
             enum_log_type log_type,
             const char *new_name,
             enum cache_type io_cache_type_arg);
@@ -223,6 +227,10 @@ public:
   volatile enum_log_state log_state;
   enum cache_type io_cache_type;
   friend class Log_event;
+#ifdef HAVE_PSI_INTERFACE
+  /** Instrumentation key to use for file io in @c log_file */
+  PSI_file_key m_log_file_key;
+#endif
 };
 
 class MYSQL_QUERY_LOG: public MYSQL_LOG
@@ -241,14 +249,22 @@ public:
   bool open_slow_log(const char *log_name)
   {
     char buf[FN_REFLEN];
-    return open(generate_name(log_name, "-slow.log", 0, buf), LOG_NORMAL, 0,
-                WRITE_CACHE);
+    return open(
+#ifdef HAVE_PSI_INTERFACE
+                key_file_slow_log,
+#endif
+                generate_name(log_name, "-slow.log", 0, buf),
+                LOG_NORMAL, 0, WRITE_CACHE);
   }
   bool open_query_log(const char *log_name)
   {
     char buf[FN_REFLEN];
-    return open(generate_name(log_name, ".log", 0, buf), LOG_NORMAL, 0,
-                WRITE_CACHE);
+    return open(
+#ifdef HAVE_PSI_INTERFACE
+                key_file_query_log,
+#endif
+                generate_name(log_name, ".log", 0, buf),
+                LOG_NORMAL, 0, WRITE_CACHE);
   }
 
 private:
diff --git a/sql/mysqld.cc b/sql/mysqld.cc
index 9f5f3d46e67..04e61635f22 100644
--- a/sql/mysqld.cc
+++ b/sql/mysqld.cc
@@ -7838,9 +7838,10 @@ PSI_file_key key_file_binlog, key_file_binlog_index, key_file_casetest,
   key_file_dbopt, key_file_des_key_file, key_file_ERRMSG, key_select_to_file,
   key_file_fileparser, key_file_frm, key_file_global_ddl_log, key_file_load,
   key_file_loadfile, key_file_log_event_data, key_file_log_event_info,
-  key_file_master_info, key_file_misc, key_file_MYSQL_LOG, key_file_partition,
+  key_file_master_info, key_file_misc, key_file_partition,
   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;
 
 static PSI_file_info all_server_files[]=
 {
@@ -7863,11 +7864,12 @@ static PSI_file_info all_server_files[]=
   { &key_file_log_event_info, "log_event_info", 0},
   { &key_file_master_info, "master_info", 0},
   { &key_file_misc, "misc", 0},
-  { &key_file_MYSQL_LOG, "MYSQL_LOG", 0},
   { &key_file_partition, "partition", 0},
   { &key_file_pid, "pid", 0},
+  { &key_file_query_log, "query_log", 0},
   { &key_file_relay_log_info, "relay_log_info", 0},
   { &key_file_send_file, "send_file", 0},
+  { &key_file_slow_log, "slow_log", 0},
   { &key_file_tclog, "tclog", 0},
   { &key_file_trg, "trigger_name", 0},
   { &key_file_trn, "trigger", 0},
diff --git a/sql/mysqld.h b/sql/mysqld.h
index dc9f94c0d03..113bc3aa983 100644
--- a/sql/mysqld.h
+++ b/sql/mysqld.h
@@ -270,9 +270,10 @@ extern PSI_file_key key_file_binlog, key_file_binlog_index, key_file_casetest,
   key_file_dbopt, key_file_des_key_file, key_file_ERRMSG, key_select_to_file,
   key_file_fileparser, key_file_frm, key_file_global_ddl_log, key_file_load,
   key_file_loadfile, key_file_log_event_data, key_file_log_event_info,
-  key_file_master_info, key_file_misc, key_file_MYSQL_LOG, key_file_partition,
+  key_file_master_info, key_file_misc, key_file_partition,
   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;
 
 void init_server_psi_keys();
 #endif /* HAVE_PSI_INTERFACE */