#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#58052 | Marc Alff | 12 Nov |
