In Introduction to Instruments I have covered what instruments are (which is a part of performance schema), how they look like and where can you find it in i.e. setup_instruments table of performance_schema. I have also covered how a DBA can make use of it . There are 1016 set of instrument in MySQL 5.7.17 which is more than what we have in 5.6. A DBA can enable/disable them as per your needs.

In structure of this table there are 3 columns i.e. Name,Enabled,Timed

mysql> show create table setup_instruments;
+-------------------+--------------------------------------------------------
| Table | Create Table |
+-------------------+--------------------------------------------------------
| setup_instruments | CREATE TABLE `setup_instruments` (
`NAME` varchar(128) NOT NULL,
`ENABLED` enum('YES','NO') NOT NULL,
`TIMED` enum('YES','NO') NOT NULL
) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8 |
+-------------------+--------------------------------------------------------
1 row in set (0.00 sec)

So we have multiple instruments, like I pasted below for alter_db, drop_function, repair etc. For these instrument we can check why it is taking time and where the query is spending most of the time.

statement/sql/alter_db
statement/sql/repair 
statement/sql/replace 
statement/sql/replace_select
statement/sql/create_udf
statement/sql/drop_function
statement/sql/revoke
statement/sql/optimize

Hence we can check which instruments are enabled as shown below:

mysql> select * from setup_instruments where ENABLED ='YES';
+----------------------------------------------------------------------------
| NAME | ENABLED | TIMED |
+--------------------------------------------------------------------------------+---------+-------+
| wait/io/file/sql/map | YES | YES |
| wait/io/file/sql/binlog | YES | YES |
| wait/io/file/sql/binlog_cache | YES | YES |
327 rows in set (0.00 sec)

To enable all these instrument , please ensure that performance_schema must be ON :

mysql> show global variables like '%performance_schema%';
+----------------------------------------------------------+-------+
| Variable_name | Value |
+----------------------------------------------------------+-------+
| performance_schema | ON |
+----------------------------------------------------------+-------+

Now , there is one more table known as setup_consumers, which provides the information stored about “”instrument”” . What i mean by this is “What kind of data will be stored in the related ( BY RELATED I MEAN , WHAT KIND OF DATA WILL BE LOGGED TO MONITOR THE PERFORMANCE IN TABLE)”.

In below table, only event_statement_current and event_statement_history is turned ON which means all information related to DDL/DML statement will be logged.

mysql> select * from setup_consumers;
+----------------------------------+---------+
| NAME | ENABLED |
+----------------------------------+---------+
| events_stages_current | NO |
| events_stages_history | NO |
| events_stages_history_long | NO |
| events_statements_current | YES |
| events_statements_history | YES |
| events_statements_history_long | NO |
| events_transactions_current | NO |
| events_transactions_history | NO |
| events_transactions_history_long | NO |
| events_waits_current | NO |
| events_waits_history | NO |
| events_waits_history_long | NO |
| global_instrumentation | YES |
| thread_instrumentation | YES |
| statements_digest | YES |  < -------------- This is useful , we will cover it in this chapter.
+----------------------------------+---------+

So in above output, we can see that event_statement_current and event_statement_history is turned ON, which means current and historical data will be saved. So very soon we will see what these tables will show us. Please note that for every monitor, performance_schema has respective tables.

Please note that all these “instrument” are event name in events table.
Lets select some records from one of the event table events_statements_current and try to understand what information it provides:

mysql> select * from events_statements_current limit 1\G;
*************************** 1. row ***************************
THREAD_ID: 807336 <- This is Thread ID
EVENT_ID: 23739
END_EVENT_ID: 23739
EVENT_NAME: statement/sql/set_option ##### "This is instrument name" .
SOURCE: socket_connection.cc:95 ###### This is source code (https://github.com/bjoernv/mysql-packaging)
TIMER_START: 591734569357461000 ###### Start Time in PICO SECOND.
TIMER_END: 591734569450550000 ####### End time in pico second
TIMER_WAIT: 93089000 ###### Waiting time in pico second
LOCK_TIME: 0 ######## lock time in pico second
SQL_TEXT: SET autocommit=1  ###### Query
DIGEST: 54b0116d21e24f638f94bd799148b397
DIGEST_TEXT: SET `autocommit` = ?  ###### Shows same output for other values in SQL
CURRENT_SCHEMA: cim_user2
OBJECT_TYPE: NULL
OBJECT_SCHEMA: NULL
OBJECT_NAME: NULL
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: 00000
MESSAGE_TEXT: NULL
ERRORS: 0
WARNINGS: 0
ROWS_AFFECTED: 0
ROWS_SENT: 0
ROWS_EXAMINED: 0
CREATED_TMP_DISK_TABLES: 0
CREATED_TMP_TABLES: 0
SELECT_FULL_JOIN: 0
SELECT_FULL_RANGE_JOIN: 0
SELECT_RANGE: 0
SELECT_RANGE_CHECK: 0
SELECT_SCAN: 0
SORT_MERGE_PASSES: 0
SORT_RANGE: 0
SORT_ROWS: 0
SORT_SCAN: 0
NO_INDEX_USED: 0
NO_GOOD_INDEX_USED: 0
NESTING_EVENT_ID: NULL
NESTING_EVENT_TYPE: NULL
NESTING_EVENT_LEVEL: 0
1 row in set (0.00 sec)

Taking an another example of its usage, in case we want to see all those current queries which has lock_time > 0 below query will give us the data and then we can optimise the query mentioned in SQL_TEXT.

select * from events_statements_current where lock_time > 0;

Let’s evaluate statements_digest . This is very useful tool in identifying slow queries if queries are not using index, how much time this query ran etc.

*************************** 1. row ***************************
SCHEMA_NAME: ABC
DIGEST: 83b9e1dc432459828ed9a4d65aef7efe
DIGEST_TEXT: SELECT `A` , COUNT (?) FROM `ABC` . `C` WHERE `ID` IN (...) GROUP BY `ID`
COUNT_STAR: 4283945 <-------- This query ran this number of time.
SUM_TIMER_WAIT: 12795126000
MIN_TIMER_WAIT: 12795126000
AVG_TIMER_WAIT: 12795126000
MAX_TIMER_WAIT: 12795126000
SUM_LOCK_TIME: 1068000000 <----- Total lock time
SUM_ERRORS: 0 <- No errors
SUM_WARNINGS: 0
SUM_ROWS_AFFECTED: 0
SUM_ROWS_SENT: 4
SUM_ROWS_EXAMINED: 357 <-- number of examined rows
SUM_CREATED_TMP_DISK_TABLES: 0   <--- if any temporary tables
SUM_CREATED_TMP_TABLES: 1
SUM_SELECT_FULL_JOIN: 0 <---- Full joins
SUM_SELECT_FULL_RANGE_JOIN: 0 <--- Full range join
SUM_SELECT_RANGE: 1
SUM_SELECT_RANGE_CHECK: 0
SUM_SELECT_SCAN: 0
SUM_SORT_MERGE_PASSES: 0
SUM_SORT_RANGE: 0
SUM_SORT_ROWS: 4
SUM_SORT_SCAN: 1
SUM_NO_INDEX_USED: 0 <- No index used
SUM_NO_GOOD_INDEX_USED: 0
FIRST_SEEN: 2018-05-25 16:35:38 <- Query ran first time
LAST_SEEN: 2018-05-25 16:35:38 <- Query ran last time

This is equivalent to pt_query_digest tool from Percona tool kit.

So now it is easy to keep track of various queries before putting it in production and we can monitor as well and in this way you can enable / disable instrument using below command :

update setup_instruments set enabled='NO' where name like '%IO%';

Taking one more example, now i want to check most frequent events waiting. For this we have table :

mysql> select * from events_waits_summary_global_by_event_name where count_star >0 order by count_star desc limit 1\G;
*************************** 1. row ***************************
EVENT_NAME: wait/io/table/sql/handler
COUNT_STAR: 42057624429
SUM_TIMER_WAIT: 77766263675607248
MIN_TIMER_WAIT: 51448
AVG_TIMER_WAIT: 1848640
MAX_TIMER_WAIT: 227940787813800

Taking another example of most frequent time a FILE has waited. Below query shows, most frequent file event in READ. So in this example innodb_data_file read most:

mysql> select * from file_summary_by_event_name where count_read > 0 order by count_read desc limit 1\G;
*************************** 1. row ***************************
EVENT_NAME: wait/io/file/innodb/innodb_data_file
COUNT_STAR: 15766760
SUM_TIMER_WAIT: 10702863789499124
MIN_TIMER_WAIT: 0
AVG_TIMER_WAIT: 678824532
MAX_TIMER_WAIT: 509288622556
COUNT_READ: 9928666
SUM_TIMER_READ: 8695743706041360
MIN_TIMER_READ: 4804284
AVG_TIMER_READ: 875821540
MAX_TIMER_READ: 509288622556
SUM_NUMBER_OF_BYTES_READ: 162674245632
COUNT_WRITE: 4379186
SUM_TIMER_WRITE: 169500476525368
MIN_TIMER_WRITE: 4417552
AVG_TIMER_WRITE: 38705900
MAX_TIMER_WRITE: 33147286296
SUM_NUMBER_OF_BYTES_WRITE: 73817784320
COUNT_MISC: 1458908
SUM_TIMER_MISC: 1837619606932396
MIN_TIMER_MISC: 0
AVG_TIMER_MISC: 1259585252
MAX_TIMER_MISC: 37993360460
1 row in set (0.01 sec)

Similarly to identify the files which were being written most, can be done using below :

mysql> select * from file_summary_by_event_name where count_write > 0 order by count_write desc limit 1\G;
*************************** 1. row ***************************
EVENT_NAME: wait/io/file/sql/binlog
COUNT_STAR: 7611571
SUM_TIMER_WAIT: 1142126255583392
MIN_TIMER_WAIT: 0
AVG_TIMER_WAIT: 150051144
MAX_TIMER_WAIT: 56774758932
COUNT_READ: 918412
SUM_TIMER_READ: 8858813984764
MIN_TIMER_READ: 0
AVG_TIMER_READ: 9645628
MAX_TIMER_READ: 20452624404
SUM_NUMBER_OF_BYTES_READ: 6591392330
COUNT_WRITE: 4658695
SUM_TIMER_WRITE: 102365348448260
MIN_TIMER_WRITE: 3264768
AVG_TIMER_WRITE: 21972656
MAX_TIMER_WRITE: 24619224396
SUM_NUMBER_OF_BYTES_WRITE: 3369255287
COUNT_MISC: 2034464
SUM_TIMER_MISC: 1030902093150368
MIN_TIMER_MISC: 0
AVG_TIMER_MISC: 506719200
MAX_TIMER_MISC: 56774758932

This will help a DBA to identify the files get write most or read most or events or queries that needs optimisation.

About Ankit Kapoor

Ankit Kapoor is a database geek and enjoy playing with open source databases like MySQL and PG and Myrocks.
Connect with me on linkedin