Bug #76225 Instrumentation for binlog cache file
Submitted: 9 Mar 2015 12:26 Modified: 30 Sep 2015 17:31
Reporter: Daniël van Eeden (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S3 (Non-critical)
Version:5.6, 5.6.25 OS:Any
Assigned to: Chris Powers CPU Architecture:Any
Tags: binlog

[9 Mar 2015 12:26] Daniël van Eeden
Description:
Binlog cache files are created as @@tmpdir/ML<random> (e.g. /tmp/MLu7bIsu).

I couldn't find an performance_schema event for the I/O on these files.

How to repeat:
mysql> SELECT NAME FROM setup_instruments WHERE NAME LIKE '%binlog%';
+---------------------------------------------------------------------------------+
| NAME                                                                            |
+---------------------------------------------------------------------------------+
| wait/synch/rwlock/sql/Binlog_transmit_delegate::lock                            |
| wait/synch/rwlock/sql/Binlog_relay_IO_delegate::lock                            |
| wait/synch/rwlock/sql/Binlog_storage_delegate::lock                             |
| wait/io/file/sql/binlog                                                         |
| wait/io/file/sql/binlog_index                                                   |
| stage/sql/Finished reading one binlog; switching to next binlog                 |
| stage/sql/Master has sent all binlog to slave; waiting for binlog to be updated |
| stage/sql/Requesting binlog dump                                                |
| stage/sql/Sending binlog event to slave                                         |
| statement/sql/show_binlogs                                                      |
| statement/sql/show_binlog_events                                                |
| statement/sql/binlog                                                            |
| statement/com/Binlog Dump                                                       |
| statement/com/Binlog Dump GTID                                                  |
+---------------------------------------------------------------------------------+
14 rows in set (0.00 sec)

The ML prefix is from LOG_PREFIX:
https://github.com/mysql/mysql-server/blob/f964f6b37337b98d467c1e9fb7914c1655a08e84/sql/un...

mysql> select * from setup_instruments where name like 'wait/io/file/%';
+--------------------------------------+---------+-------+
| NAME                                 | ENABLED | TIMED |
+--------------------------------------+---------+-------+
| wait/io/file/sql/map                 | YES     | YES   |
| wait/io/file/sql/binlog              | YES     | YES   |
| wait/io/file/sql/binlog_index        | YES     | YES   |
| wait/io/file/sql/relaylog            | YES     | YES   |
| wait/io/file/sql/relaylog_index      | YES     | YES   |
| wait/io/file/sql/casetest            | YES     | YES   |
| wait/io/file/sql/dbopt               | YES     | YES   |
| wait/io/file/sql/des_key_file        | YES     | YES   |
| wait/io/file/sql/ERRMSG              | YES     | YES   |
| wait/io/file/sql/select_to_file      | YES     | YES   |
| wait/io/file/sql/file_parser         | YES     | YES   |
| wait/io/file/sql/FRM                 | YES     | YES   |
| wait/io/file/sql/global_ddl_log      | YES     | YES   |
| wait/io/file/sql/load                | YES     | YES   |
| wait/io/file/sql/LOAD_FILE           | YES     | YES   |
| wait/io/file/sql/log_event_data      | YES     | YES   |
| wait/io/file/sql/log_event_info      | YES     | YES   |
| wait/io/file/sql/master_info         | YES     | YES   |
| wait/io/file/sql/misc                | YES     | YES   |
| wait/io/file/sql/partition           | YES     | YES   |
| wait/io/file/sql/pid                 | YES     | YES   |
| wait/io/file/sql/query_log           | YES     | YES   |
| wait/io/file/sql/relay_log_info      | YES     | YES   |
| wait/io/file/sql/send_file           | YES     | YES   |
| wait/io/file/sql/slow_log            | YES     | YES   |
| wait/io/file/sql/tclog               | YES     | YES   |
| wait/io/file/sql/trigger_name        | YES     | YES   |
| wait/io/file/sql/trigger             | YES     | YES   |
| wait/io/file/sql/init                | YES     | YES   |
| wait/io/file/mysys/proc_meminfo      | YES     | YES   |
| wait/io/file/mysys/charset           | YES     | YES   |
| wait/io/file/mysys/cnf               | YES     | YES   |
| wait/io/file/myisam/data_tmp         | YES     | YES   |
| wait/io/file/myisam/dfile            | YES     | YES   |
| wait/io/file/myisam/kfile            | YES     | YES   |
| wait/io/file/myisam/log              | YES     | YES   |
| wait/io/file/csv/metadata            | YES     | YES   |
| wait/io/file/csv/data                | YES     | YES   |
| wait/io/file/csv/update              | YES     | YES   |
| wait/io/file/myisammrg/MRG           | YES     | YES   |
| wait/io/file/innodb/innodb_data_file | YES     | YES   |
| wait/io/file/innodb/innodb_log_file  | YES     | YES   |
| wait/io/file/innodb/innodb_temp_file | YES     | YES   |
| wait/io/file/archive/metadata        | YES     | YES   |
| wait/io/file/archive/data            | YES     | YES   |
| wait/io/file/archive/FRM             | YES     | YES   |
+--------------------------------------+---------+-------+
46 rows in set (0.00 sec)

mysql> \! lsof +L1
COMMAND  PID  USER   FD   TYPE DEVICE SIZE/OFF NLINK NODE NAME
mysqld  6243 mysql    5u   REG  253,3     9622     0   12 /tmp/iblHOAoy (deleted)
mysqld  6243 mysql    6u   REG  253,3        0     0   13 /tmp/ibODbKcR (deleted)
mysqld  6243 mysql    7u   REG  253,3        0     0   14 /tmp/ibz9LT09 (deleted)
mysqld  6243 mysql    8u   REG  253,3        0     0   15 /tmp/ibQAjNtM (deleted)
mysqld  6243 mysql   12u   REG  253,3        0     0   16 /tmp/iblTw3y6 (deleted)
mysqld  6243 mysql   27u   REG  253,3        0     0   18 /tmp/MLRNOPCi (deleted)
mysqld  6243 mysql   29u   REG  253,3        0     0   23 /tmp/MLTm4BNx (deleted)
mysqld  6243 mysql   84u   REG  253,3        0     0   21 /tmp/MLThEAl0 (deleted)
mysqld  6243 mysql   91u   REG  253,3        0     0   19 /tmp/MLzQI4kH (deleted)
mysqld  6243 mysql   94u   REG  253,3        0     0   22 /tmp/ML5XBndu (deleted)
mysqld  6243 mysql   95u   REG  253,3        0     0   17 /tmp/MLKKpGxi (deleted)
mysql> SELECT * FROM file_instances WHERE FILE_NAME LIKE '/tmp%';
Empty set (0.00 sec)

mysql> SELECT COUNT(*) FROM file_instances;
+----------+
| COUNT(*) |
+----------+
|      373 |
+----------+
1 row in set (0.00 sec)

It looks like the the /tmp/ib* files are also not instrumented.
[10 Mar 2015 6:07] Umesh Shastry
Hello Daniël van Eeden,

Thank you for the report.

Thanks,
Umesh
[30 Sep 2015 17:31] Paul Dubois
Noted in 5.7.9, 5.8.0 changelogs.

The Performance Schema now includes these instruments for monitoring
I/O on binary log and relay log cache files:

wait/io/file/sql/binlog_cache
wait/io/file/sql/binlog_index_cache
wait/io/file/sql/relaylog_cache
wait/io/file/sql/relaylog_index_cache

In addition, the default value of performance_schema_max_file_classes
has been increased from 50 to 80.