Bug #58052 Binary log IO not being accounted for properly
Submitted: 8 Nov 2010 14:16 Modified: 11 Dec 2010 17:09
Reporter: Mark Leith Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.5.6 OS:Any
Assigned to: Marc ALFF CPU Architecture:Any

[8 Nov 2010 14:16] Mark Leith
Description:
Binary log IO instrumentation does not appear to work, at least on OSX and Linux 64bit.

mysql> show global variables like 'log_bin';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_bin       | ON    |
+---------------+-------+
1 row in set (0.00 sec)

mysql> select * from FILE_SUMMARY_BY_EVENT_NAME where EVENT_NAME like 'wait/io/file/sql/binlog%'\G
*************************** 1. row ***************************
               EVENT_NAME: wait/io/file/sql/binlog
               COUNT_READ: 0
              COUNT_WRITE: 0
 SUM_NUMBER_OF_BYTES_READ: 0
SUM_NUMBER_OF_BYTES_WRITE: 0
*************************** 2. row ***************************
               EVENT_NAME: wait/io/file/sql/binlog_index
               COUNT_READ: 0
              COUNT_WRITE: 0
 SUM_NUMBER_OF_BYTES_READ: 0
SUM_NUMBER_OF_BYTES_WRITE: 0
2 rows in set (0.00 sec)

mysql> show master status;
+------------------+----------+--------------+------------------+
| File             | Position | Binlog_Do_DB | Binlog_Ignore_DB |
+------------------+----------+--------------+------------------+
| mysql-bin.000022 | 53456618 |              |                  |
+------------------+----------+--------------+------------------+
1 row in set (0.00 sec)

mysql> show global status like 'Binlog%';
+-----------------------+---------+
| Variable_name         | Value   |
+-----------------------+---------+
| Binlog_cache_disk_use | 9       |
| Binlog_cache_use      | 2418965 |
+-----------------------+---------+
2 rows in set (0.00 sec)

How to repeat:
o Enable log_bin

use test;
create table t1 (i int);
insert into t1 values (1);
select * from performance_schema.FILE_SUMMARY_BY_EVENT_NAME where EVENT_NAME like 'wait/io/file/sql/binlog%'\G
[12 Nov 2010 6:25] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/123684

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"
[15 Nov 2010 2:24] Christopher Powers
Patch approved.
[16 Nov 2010 6:45] Marc ALFF
Patch queued into:
- mysql-5.5-bugteam
- mysql-trunk-bugfixing
[5 Dec 2010 12:42] Bugs System
Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (version source revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (merge vers: 5.6.1) (pib:23)
[11 Dec 2010 17:09] Paul DuBois
Noted in 5.5.8 changelog.

Performance Schema did not account for file I/O for the binary log
file (no I/O was counted).
[16 Dec 2010 22:33] Bugs System
Pushed into mysql-5.5 5.5.9 (revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (version source revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (merge vers: 5.5.9) (pib:24)