List:Commits« Previous MessageNext Message »
From:Marc Alff Date:November 12 2010 6:23am
Subject:bzr commit into mysql-5.5-bugteam branch (marc.alff:3120) Bug#58052
View as plain text  
#At file:///Users/malff/BZR_TREE/mysql-5.5-bugteam-58052/ based on revid:svoj@stripped

 3120 Marc Alff	2010-11-12
      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"

    modified:
      mysys/mf_iocache.c
      sql/log.cc
      sql/log.h
      sql/mysqld.cc
      sql/mysqld.h
=== modified file 'mysys/mf_iocache.c'
--- a/mysys/mf_iocache.c	2010-07-29 12:32:11 +0000
+++ b/mysys/mf_iocache.c	2010-11-12 06:23:26 +0000
@@ -173,7 +173,7 @@ int init_io_cache(IO_CACHE *info, File f
 
   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 f
     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, 
   */
   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, 
       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, 
     }
     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 *cach
         */
         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 *cach
             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 *in
     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 *in
     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 *in
   }
   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 *
       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 *
     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 *
     }
     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,
         "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,
   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 *in
   {
     /* 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;

=== modified file 'sql/log.cc'
--- a/sql/log.cc	2010-10-20 19:02:59 +0000
+++ b/sql/log.cc	2010-11-12 06:23:26 +0000
@@ -2177,7 +2177,11 @@ bool MYSQL_LOG::init_and_set_log_file_na
     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_nam
 
   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
   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();

=== modified file 'sql/log.h'
--- a/sql/log.h	2010-09-29 14:26:32 +0000
+++ b/sql/log.h	2010-11-12 06:23:26 +0000
@@ -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:

=== modified file 'sql/mysqld.cc'
--- a/sql/mysqld.cc	2010-11-09 15:59:33 +0000
+++ b/sql/mysqld.cc	2010-11-12 06:23:26 +0000
@@ -7838,9 +7838,10 @@ PSI_file_key key_file_binlog, key_file_b
   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},

=== modified file 'sql/mysqld.h'
--- a/sql/mysqld.h	2010-11-05 13:16:27 +0000
+++ b/sql/mysqld.h	2010-11-12 06:23:26 +0000
@@ -270,9 +270,10 @@ extern PSI_file_key key_file_binlog, key
   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 */


Attachment: [text/bzr-bundle] bzr/marc.alff@oracle.com-20101112062326-zoucnvttncm801nl.bundle
Thread
bzr commit into mysql-5.5-bugteam branch (marc.alff:3120) Bug#58052Marc Alff12 Nov