Table of contents
Preamble
Performance Schema is a cool DBA feature for monitoring server runtime events execution at low level. Same as for other database flavors an “event” is anything the server does that takes time and has been instrumented so that timing information can be collected. An event is anything in a function call, an IOPS, an operating system wait, SQL statement stage i.e execution such as parsing or sorting, or an entire statement or group of statements. It helps DBA answering the classical developers question: my process was slow can you check the database ? It is implemented using the PERFORMANCE_SCHEMA storage engine and the performance_schema database. Opposite to INFORMATION_SCHEMA that provide metadata information.
It is also written that activating Performance Schema will have minimal impact on server performance, but I plan to have a formal check on this at the end of the part 2 of this blog serie.
Times in performance Schema tables are in picoseconds (trillionths of a second, abbreviated as ps) i.e. 10^-12 of a second i.e. 10^-9 of a millisecond (wait events are usually more reported in milliseconds).
Even is it’s hard for me to write it but the Oracle MySQL documentation is far much better than the MariaDB one. So even if my testing has been done on MariaDB I have mainly used the Oracle MySQL documentation…
My test server has 64MB with 12 cores (24 threads) and is running with Red Hat Enterprise Linux release 8.7 (Ootpa). My MariaDB Community edition database is 10.11.6 and I’m using sysbench 1.0.20 to generate some workload to have some figures to report in my blog post.
Performance schema activation and configuration
You have a set of Performance Schema system variables and the main one to change is performance_schema:
MariaDB [(none)]> show variables like 'performance_schema%'; +----------------------------------------------------------+-------+ | Variable_name | Value | +----------------------------------------------------------+-------+ | performance_schema | ON | . . . | performance_schema_users_size | -1 | +----------------------------------------------------------+-------+ 42 rows in set (0.002 sec) |
Then the activation of what to collect is in setup_consumers table, by default you should see something like:
MariaDB [(none)]> select * from performance_schema.setup_consumers order by name; +----------------------------------+---------+ | NAME | ENABLED | +----------------------------------+---------+ | events_stages_current | NO | | events_stages_history | NO | | events_stages_history_long | NO | | events_statements_current | NO | | events_statements_history | NO | | 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 | | statements_digest | YES | | thread_instrumentation | YES | +----------------------------------+---------+ 15 rows in set (0.000 sec) |
The hierarchy of values is the following:
global_instrumentation
thread_instrumentation
events_waits_current
events_waits_history
events_waits_history_long
events_stages_current
events_stages_history
events_stages_history_long
events_statements_current
events_statements_history
events_statements_history_long
events_transactions_current
events_transactions_history
events_transactions_history_long
statements_digest |
Remark:
Statement digest is a hashing of SQL statements giving you the capability to group similar statement (similar to sql_id with Oracle). Similar in the way that fixed value are replaced by bind variables and a question mark character will replace them.
This performance_schema.setup_consumers must be correlated with performance_schema.setup_instruments to activate lists classes of instrumented objects for which events can be collected. For example I had all transactions related tables with all counter set to zero simply because by default the instrument is not enables and timed:
MariaDB [(none)]> select * from performance_schema.setup_instruments where name like 'transaction%'; +-------------+---------+-------+ | NAME | ENABLED | TIMED | +-------------+---------+-------+ | transaction | NO | NO | +-------------+---------+-------+ 1 row in set (0.001 sec) MariaDB [(none)]> update performance_schema.setup_instruments set enabled='YES',timed='YES' where name='transaction'; Query OK, 1 row affected (0.001 sec) Rows matched: 1 Changed: 1 Warnings: 0 |
Updating the performance_schema.setup_instruments table does not resist of a bounce of the instance, to make it persistent update your my.cnf and add:
performance-schema-instrument='transaction=ON' |
Same as transaction instrumentation the stage one is not massively activated by default (but be careful before fully activating it from performance standpoint):
MariaDB [(none)]> select enabled,count(*) from performance_schema.setup_instruments where name like 'stage%' group by enabled; +---------+----------+ | enabled | count(*) | +---------+----------+ | YES | 8 | | NO | 149 | +---------+----------+ 2 rows in set (0.002 sec) |
You get a status of Performance Schema memory usage doing:
MariaDB [(none)]> show engine performance_schema status; +--------------------+-------------------------------------------------------------+-----------+ | Type | Name | Status | +--------------------+-------------------------------------------------------------+-----------+ | performance_schema | events_waits_current.size | 176 | | performance_schema | events_waits_current.count | 1536 | . . . |
Performance Schema with global instrumentation Only
With global instrumentation only you already have an access to a bunch of interesting figures. We can start with plenty on interesting queries for global wait events of your instance. All the wait events and their meaning are explained in official documentation.
The global instance wait by event names:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(min_timer_wait*pow(10,-9),3) as min_timer_wait_msec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, round(max_timer_wait*pow(10,-9),3) as max_timer_wait_msec from performance_schema.events_waits_summary_global_by_event_name order by sum_timer_wait desc limit 10; +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | event_name | count_star | sum_timer_wait_sec | min_timer_wait_msec | avg_timer_wait_msec | max_timer_wait_msec | +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | idle | 97621363 | 663203 | 0.001 | 6.793 | 28800069.218 | | wait/io/table/sql/handler | 2120085693 | 9236 | 0.005 | 0.004 | 4467.994 | | wait/io/file/innodb/innodb_data_file | 3773451 | 1280 | 0.000 | 0.339 | 1168.647 | | wait/io/file/aria/MAD | 27177 | 174 | 0.000 | 6.401 | 1513.599 | | wait/io/file/sql/binlog | 4758900 | 148 | 0.000 | 0.031 | 658.594 | | wait/lock/table/sql/handler | 90644994 | 57 | 0.000 | 0.001 | 13.007 | | wait/io/file/aria/MAI | 99095 | 37 | 0.000 | 0.369 | 1616.183 | | wait/io/file/sql/FRM | 949 | 4 | 0.000 | 4.303 | 1508.488 | | wait/io/file/sql/slow_log | 4589 | 0 | 0.001 | 0.046 | 0.414 | | wait/io/file/sql/dbopt | 24 | 0 | 0.001 | 2.045 | 20.655 | +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ 10 rows in set (0.011 sec) |
The stages (statement processing, such as sorting result or sending data) wait event instrumentation is poorly activated, as such most counter are equal to 0:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(min_timer_wait*pow(10,-9),3) as min_timer_wait_msec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, round(max_timer_wait*pow(10,-9),3) as max_timer_wait_msec from performance_schema.events_stages_summary_global_by_event_name order by sum_timer_wait desc limit 10; +----------------------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | event_name | count_star | sum_timer_wait_sec | min_timer_wait_msec | avg_timer_wait_msec | max_timer_wait_msec | +----------------------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | stage/innodb/buffer pool load | 1 | 5 | 4738.595 | 4738.595 | 4738.595 | | stage/sql/Writing to binlog | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/Apply log event | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/preparing for alter table | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/Committing alter table to storage engine | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/altering table | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/Allocating local table | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/After table lock | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/After opening tables | 0 | 0 | 0.000 | 0.000 | 0.000 | | stage/sql/After create | 0 | 0 | 0.000 | 0.000 | 0.000 | +----------------------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ |
Statement global wait events (better to display it in a graphical query tool like HeidiSQL):
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, sum_lock_time, sum_errors, sum_warnings, sum_rows_affected, sum_rows_sent, sum_rows_examined, sum_created_tmp_disk_tables, sum_created_tmp_tables, sum_select_full_join, sum_select_full_range_join, sum_select_range, sum_select_range_check, sum_select_scan, sum_sort_merge_passes, sum_sort_range, sum_sort_rows, sum_sort_scan, sum_no_index_used, sum_no_good_index_used from performance_schema.events_statements_summary_global_by_event_name order by sum_timer_wait desc limit 10; +-------------------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | sum_lock_time | sum_errors | sum_warnings | sum_rows_affected | sum_rows_sent | sum_rows_examined | sum_created_tmp_disk_tables | sum_created_tmp_tables | sum_select_full_join | sum_select_full_range_join | sum_select_range | sum_select_range_check | sum_select_scan | sum_sort_merge_passes | sum_sort_range | sum_sort_rows | sum_sort_scan | sum_no_index_used | sum_no_good_index_used | +-------------------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ | statement/sql/select | 70165341 | 14816 | 0.211 | 2154116665000000 | 3 | 2 | 0 | 1558877826 | 3560663935 | 3882 | 5015978 | 1646 | 0 | 20046216 | 0 | 6294 | 0 | 5011453 | 1002469678 | 5013363 | 4648 | 0 | | statement/sql/update | 9997758 | 5392 | 0.539 | 375109038000000 | 0 | 0 | 9997758 | 0 | 9997758 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/insert | 4998980 | 1174 | 0.235 | 227068347000000 | 0 | 0 | 5023259 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/delete | 4998980 | 1167 | 0.233 | 142076827000000 | 0 | 0 | 4998980 | 0 | 4998995 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/commit | 5035833 | 1073 | 0.213 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/begin | 5035833 | 167 | 0.033 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/show_table_status | 62 | 25 | 410.260 | 756298000000 | 0 | 0 | 0 | 578 | 578 | 38 | 282 | 0 | 0 | 0 | 0 | 62 | 0 | 0 | 0 | 0 | 62 | 0 | | statement/sql/show_triggers | 6 | 5 | 874.184 | 5235015000000 | 0 | 0 | 0 | 0 | 0 | 6 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | | statement/sql/show_procedure_status | 6 | 5 | 863.453 | 5174505000000 | 0 | 0 | 0 | 52 | 52 | 6 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | | statement/sql/show_function_status | 6 | 4 | 626.090 | 3744502000000 | 0 | 0 | 0 | 44 | 44 | 6 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | 0 | 0 | 0 | 6 | 0 | +-------------------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ 10 rows in set (0.002 sec) |
With HeidiSQL it gives:
Transactions global wait events:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec from performance_schema.events_transactions_summary_global_by_event_name order by sum_timer_wait desc limit 10; +-------------+------------+--------------------+---------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | +-------------+------------+--------------------+---------------------+ | transaction | 1780067 | 8504 | 4.778 | +-------------+------------+--------------------+---------------------+ 1 row in set (0.001 sec) |
Global wait summary by instance:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(min_timer_wait*pow(10,-9),3) as min_timer_wait_msec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, round(max_timer_wait*pow(10,-9),3) AS max_timer_wait_msec from performance_schema.events_waits_summary_by_instance order by sum_timer_wait desc limit 10; +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | event_name | count_star | sum_timer_wait_sec | min_timer_wait_msec | avg_timer_wait_msec | max_timer_wait_msec | +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ | wait/io/file/sql/binlog | 1207359 | 66 | 0.001 | 0.055 | 648.748 | | wait/io/file/innodb/innodb_data_file | 123633 | 49 | 0.001 | 0.396 | 1168.647 | | wait/io/file/innodb/innodb_data_file | 123717 | 48 | 0.001 | 0.390 | 210.566 | | wait/io/file/innodb/innodb_data_file | 123764 | 47 | 0.001 | 0.378 | 202.756 | | wait/io/file/innodb/innodb_data_file | 124428 | 46 | 0.001 | 0.368 | 226.806 | | wait/io/file/innodb/innodb_data_file | 124038 | 46 | 0.001 | 0.368 | 228.205 | | wait/io/file/innodb/innodb_data_file | 123804 | 45 | 0.001 | 0.367 | 381.530 | | wait/io/file/innodb/innodb_data_file | 123627 | 45 | 0.001 | 0.360 | 211.168 | | wait/io/file/innodb/innodb_data_file | 123063 | 44 | 0.001 | 0.357 | 665.127 | | wait/io/file/innodb/innodb_data_file | 124098 | 44 | 0.001 | 0.352 | 208.611 | +--------------------------------------+------------+--------------------+---------------------+---------------------+---------------------+ 10 rows in set (0.006 sec) |
Remark:
Coming back to the query on events_waits_summary_by_instance, I have plenty of time wait/io/file/innodb/innodb_data_file that is a wait for a file operation to complete because I have set innodb_file_per_table = on and each sysbench table has its own InnodDB file. I have also multiple wait/io/file/sql/binlog because each archived binary log has also its own set of IOPS waits.
We can correlate this first query with two other tables. You should also convert the picoseconds and bytes in something more human readable. In the first one we can, for example, get the bytes read and written::
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, round(sum_number_of_bytes_read/1024/1024) as sum_number_of_bytes_read_mb, round(sum_number_of_bytes_write/1024/1024) as sum_number_of_bytes_write_mb from performance_schema.file_summary_by_event_name order by sum_timer_wait desc limit 20; +--------------------------------------+------------+--------------------+---------------------+-----------------------------+------------------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | sum_number_of_bytes_read_mb | sum_number_of_bytes_write_mb | +--------------------------------------+------------+--------------------+---------------------+-----------------------------+------------------------------+ | wait/io/file/innodb/innodb_data_file | 3773451 | 1280 | 0.339 | 4291 | 92235 | | wait/io/file/sql/binlog | 4758900 | 148 | 0.031 | 0 | 3986 | | wait/io/file/aria/MAD | 7450 | 142 | 19.083 | 2 | 0 | | wait/io/file/aria/MAI | 28107 | 10 | 0.363 | 1 | 1 | | wait/io/file/sql/FRM | 949 | 4 | 4.303 | 1 | 0 | | wait/io/file/sql/slow_log | 1387 | 0 | 0.043 | 0 | 1 | | wait/io/file/sql/dbopt | 24 | 0 | 2.045 | 0 | 0 | | wait/io/file/mysys/charset | 3 | 0 | 9.126 | 0 | 0 | | wait/io/file/sql/binlog_index | 64 | 0 | 0.235 | 0 | 0 | | wait/io/file/aria/translog | 11 | 0 | 0.125 | 0 | 0 | | wait/io/file/sql/global_ddl_log | 4 | 0 | 0.272 | 0 | 0 | | wait/io/file/sql/file_parser | 101 | 0 | 0.006 | 0 | 0 | | wait/io/file/sql/casetest | 5 | 0 | 0.079 | 0 | 0 | | wait/io/file/sql/pid | 3 | 0 | 0.120 | 0 | 0 | | wait/io/file/sql/binlog_state | 6 | 0 | 0.034 | 0 | 0 | | wait/io/file/aria/control | 3 | 0 | 0.068 | 0 | 0 | | wait/io/file/sql/misc | 4 | 0 | 0.027 | 0 | 0 | | wait/io/file/innodb/innodb_temp_file | 0 | 0 | 0.000 | 0 | 0 | | wait/io/file/sql/ERRMSG | 0 | 0 | 0.000 | 0 | 0 | | wait/io/file/sql/select_to_file | 0 | 0 | 0.000 | 0 | 0 | +--------------------------------------+------------+--------------------+---------------------+-----------------------------+------------------------------+ 20 rows in set (0.002 sec) |
In the second query we can link the global generic event_names wait/io/file/innodb/innodb_data_file and wait/io/file/sql/binlog to the exact filenames (substring_index(event_name,’/’,-1) as event_name to reduce the event_name length):
select file_name, event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(sum_number_of_bytes_read/1024/1024) as sum_number_of_bytes_read_mb, round(sum_number_of_bytes_write/1024/1024) as sum_number_of_bytes_write_mb from performance_schema.file_summary_by_instance order by sum_timer_wait desc limit 20; +-----------------------------------------------+--------------------------------------+------------+--------------------+-----------------------------+------------------------------+ | file_name | event_name | count_star | sum_timer_wait_sec | sum_number_of_bytes_read_mb | sum_number_of_bytes_write_mb | +-----------------------------------------------+--------------------------------------+------------+--------------------+-----------------------------+------------------------------+ | /mariadb/logs/mariadb01/mariadb-bin.000019 | wait/io/file/sql/binlog | 1207359 | 66 | 0 | 1024 | | /mariadb/data01/mariadb01/sbtest/sbtest2.ibd | wait/io/file/innodb/innodb_data_file | 123633 | 49 | 143 | 1581 | | /mariadb/data01/mariadb01/sbtest/sbtest3.ibd | wait/io/file/innodb/innodb_data_file | 123717 | 48 | 143 | 1583 | | /mariadb/data01/mariadb01/sbtest/sbtest9.ibd | wait/io/file/innodb/innodb_data_file | 123764 | 47 | 143 | 1583 | | /mariadb/data01/mariadb01/sbtest/sbtest16.ibd | wait/io/file/innodb/innodb_data_file | 124428 | 46 | 142 | 1594 | | /mariadb/data01/mariadb01/sbtest/sbtest4.ibd | wait/io/file/innodb/innodb_data_file | 124038 | 46 | 143 | 1587 | | /mariadb/data01/mariadb01/sbtest/sbtest7.ibd | wait/io/file/innodb/innodb_data_file | 123804 | 45 | 143 | 1582 | | /mariadb/data01/mariadb01/sbtest/sbtest18.ibd | wait/io/file/innodb/innodb_data_file | 123627 | 45 | 143 | 1579 | | /mariadb/data01/mariadb01/sbtest/sbtest1.ibd | wait/io/file/innodb/innodb_data_file | 123063 | 44 | 144 | 1570 | | /mariadb/data01/mariadb01/sbtest/sbtest17.ibd | wait/io/file/innodb/innodb_data_file | 124098 | 44 | 143 | 1588 | | /mariadb/data01/mariadb01/sbtest/sbtest11.ibd | wait/io/file/innodb/innodb_data_file | 124139 | 43 | 143 | 1588 | | /mariadb/data01/mariadb01/sbtest/sbtest14.ibd | wait/io/file/innodb/innodb_data_file | 123978 | 43 | 142 | 1585 | | /mariadb/data01/mariadb01/sbtest/sbtest27.ibd | wait/io/file/innodb/innodb_data_file | 122467 | 43 | 143 | 1563 | | /mariadb/data01/mariadb01/sbtest/sbtest6.ibd | wait/io/file/innodb/innodb_data_file | 123112 | 42 | 142 | 1575 | | /mariadb/data01/mariadb01/sbtest/sbtest24.ibd | wait/io/file/innodb/innodb_data_file | 123647 | 42 | 143 | 1581 | | /mariadb/data01/mariadb01/sbtest/sbtest15.ibd | wait/io/file/innodb/innodb_data_file | 124248 | 42 | 143 | 1589 | | /mariadb/data01/mariadb01/sbtest/sbtest30.ibd | wait/io/file/innodb/innodb_data_file | 124504 | 42 | 143 | 1593 | | /mariadb/data01/mariadb01/sbtest/sbtest19.ibd | wait/io/file/innodb/innodb_data_file | 123962 | 41 | 143 | 1587 | | /mariadb/data01/mariadb01/sbtest/sbtest8.ibd | wait/io/file/innodb/innodb_data_file | 124415 | 41 | 143 | 1590 | | /mariadb/data01/mariadb01/sbtest/sbtest25.ibd | wait/io/file/innodb/innodb_data_file | 123882 | 41 | 143 | 1584 | +-----------------------------------------------+--------------------------------------+------------+--------------------+-----------------------------+------------------------------+ 20 rows in set (0.001 sec) |
To go deeper in the analysis in the minimum Performance Schema configuration you can also access to table_io_waits_summary_by_table and table_io_waits_summary_by_index_usage. For the table table_io_waits_summary_by_table that for wait event wait/io/table/sql/handler if you are doing Full Table Scan (FTS) if I’m not mistaken:
select object_type, object_name, round(sum_timer_fetch*pow(10,-12)) as sum_timer_fetch_sec, round(avg_timer_fetch*pow(10,-9),3) as avg_timer_fetch_msec, round(sum_timer_insert*pow(10,-12)) as sum_timer_insert_sec, round(avg_timer_insert*pow(10,-9),3) as avg_timer_insert_msec, round(sum_timer_update*pow(10,-12)) as sum_timer_update_sec, round(avg_timer_update*pow(10,-9),3) as avg_timer_update_msec, round(sum_timer_delete*pow(10,-12)) as sum_timer_delete_sec, round(avg_timer_delete*pow(10,-9),3) as avg_timer_delete_msec from performance_schema.table_io_waits_summary_by_table where object_schema = 'sbtest' order by sum_timer_wait desc limit 20; +-------------+-------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ | object_type | object_name | sum_timer_fetch_sec | avg_timer_fetch_msec | sum_timer_insert_sec | avg_timer_insert_msec | sum_timer_update_sec | avg_timer_update_msec | sum_timer_delete_sec | avg_timer_delete_msec | +-------------+-------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ | TABLE | sbtest14 | 140 | 0.002 | 25 | 0.146 | 166 | 0.494 | 20 | 0.119 | | TABLE | sbtest3 | 146 | 0.002 | 21 | 0.122 | 143 | 0.425 | 18 | 0.107 | | TABLE | sbtest6 | 139 | 0.002 | 23 | 0.139 | 144 | 0.429 | 21 | 0.124 | | TABLE | sbtest16 | 143 | 0.002 | 19 | 0.112 | 144 | 0.428 | 15 | 0.092 | | TABLE | sbtest25 | 138 | 0.002 | 20 | 0.117 | 145 | 0.433 | 18 | 0.106 | | TABLE | sbtest28 | 140 | 0.002 | 26 | 0.154 | 132 | 0.395 | 20 | 0.119 | | TABLE | sbtest20 | 137 | 0.002 | 21 | 0.126 | 143 | 0.428 | 17 | 0.100 | | TABLE | sbtest26 | 139 | 0.002 | 24 | 0.143 | 137 | 0.406 | 18 | 0.106 | | TABLE | sbtest12 | 139 | 0.002 | 27 | 0.161 | 127 | 0.377 | 21 | 0.127 | | TABLE | sbtest13 | 138 | 0.002 | 22 | 0.128 | 140 | 0.418 | 14 | 0.082 | | TABLE | sbtest11 | 139 | 0.002 | 19 | 0.111 | 140 | 0.416 | 14 | 0.084 | | TABLE | sbtest2 | 144 | 0.002 | 21 | 0.128 | 129 | 0.386 | 16 | 0.096 | | TABLE | sbtest23 | 138 | 0.002 | 25 | 0.151 | 126 | 0.372 | 20 | 0.116 | | TABLE | sbtest29 | 139 | 0.002 | 20 | 0.121 | 128 | 0.382 | 21 | 0.128 | | TABLE | sbtest5 | 140 | 0.002 | 20 | 0.118 | 130 | 0.387 | 17 | 0.103 | | TABLE | sbtest8 | 141 | 0.002 | 22 | 0.132 | 123 | 0.368 | 19 | 0.114 | | TABLE | sbtest17 | 141 | 0.002 | 21 | 0.127 | 129 | 0.384 | 14 | 0.081 | | TABLE | sbtest18 | 141 | 0.002 | 22 | 0.131 | 127 | 0.380 | 14 | 0.082 | | TABLE | sbtest30 | 140 | 0.002 | 28 | 0.165 | 121 | 0.358 | 15 | 0.088 | | TABLE | sbtest9 | 142 | 0.002 | 21 | 0.123 | 122 | 0.365 | 16 | 0.097 | +-------------+-------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ 20 rows in set (0.001 sec) |
As explained in the official documentation the table_io_waits_summary_by_index_usage is almost identical to table_io_waits_summary_by_table table and is also for wait/io/table/sql/handler wait event. Should be for table access by index, there is an additional column name with the index name:
select object_type, object_name, index_name, round(sum_timer_fetch*pow(10,-12)) as sum_timer_fetch_sec, round(avg_timer_fetch*pow(10,-9),3) as avg_timer_fetch_msec, round(sum_timer_insert*pow(10,-12)) as sum_timer_insert_sec, round(avg_timer_insert*pow(10,-9),3) as avg_timer_insert_msec, round(sum_timer_update*pow(10,-12)) as sum_timer_update_sec, round(avg_timer_update*pow(10,-9),3) as avg_timer_update_msec, round(sum_timer_delete*pow(10,-12)) as sum_timer_delete_sec, round(avg_timer_delete*pow(10,-9),3) as avg_timer_delete_msec from performance_schema.table_io_waits_summary_by_index_usage where object_schema = 'sbtest' order by sum_timer_wait desc limit 20; +-------------+-------------+------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ | object_type | object_name | index_name | sum_timer_fetch_sec | avg_timer_fetch_msec | sum_timer_insert_sec | avg_timer_insert_msec | sum_timer_update_sec | avg_timer_update_msec | sum_timer_delete_sec | avg_timer_delete_msec | +-------------+-------------+------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ | TABLE | sbtest14 | PRIMARY | 140 | 0.002 | 0 | 0.000 | 166 | 0.494 | 20 | 0.119 | | TABLE | sbtest3 | PRIMARY | 146 | 0.002 | 0 | 0.000 | 143 | 0.425 | 18 | 0.107 | | TABLE | sbtest6 | PRIMARY | 139 | 0.002 | 0 | 0.000 | 144 | 0.429 | 21 | 0.124 | | TABLE | sbtest16 | PRIMARY | 143 | 0.002 | 0 | 0.000 | 144 | 0.428 | 15 | 0.092 | | TABLE | sbtest25 | PRIMARY | 138 | 0.002 | 0 | 0.000 | 145 | 0.433 | 18 | 0.106 | | TABLE | sbtest20 | PRIMARY | 137 | 0.002 | 0 | 0.000 | 143 | 0.428 | 17 | 0.100 | | TABLE | sbtest26 | PRIMARY | 139 | 0.002 | 0 | 0.000 | 137 | 0.406 | 18 | 0.106 | | TABLE | sbtest11 | PRIMARY | 139 | 0.002 | 0 | 0.000 | 140 | 0.416 | 14 | 0.084 | | TABLE | sbtest28 | PRIMARY | 140 | 0.002 | 0 | 0.000 | 132 | 0.395 | 20 | 0.119 | | TABLE | sbtest13 | PRIMARY | 138 | 0.002 | 0 | 0.000 | 140 | 0.418 | 14 | 0.082 | | TABLE | sbtest2 | PRIMARY | 144 | 0.002 | 0 | 0.000 | 129 | 0.386 | 16 | 0.096 | | TABLE | sbtest29 | PRIMARY | 139 | 0.002 | 0 | 0.000 | 128 | 0.382 | 21 | 0.128 | | TABLE | sbtest12 | PRIMARY | 139 | 0.002 | 0 | 0.000 | 127 | 0.377 | 21 | 0.127 | | TABLE | sbtest5 | PRIMARY | 140 | 0.002 | 0 | 0.000 | 130 | 0.387 | 17 | 0.103 | | TABLE | sbtest23 | PRIMARY | 138 | 0.002 | 0 | 0.000 | 126 | 0.372 | 20 | 0.116 | | TABLE | sbtest8 | PRIMARY | 141 | 0.002 | 0 | 0.000 | 123 | 0.368 | 19 | 0.114 | | TABLE | sbtest17 | PRIMARY | 141 | 0.002 | 0 | 0.000 | 129 | 0.384 | 14 | 0.081 | | TABLE | sbtest18 | PRIMARY | 141 | 0.002 | 0 | 0.000 | 127 | 0.380 | 14 | 0.082 | | TABLE | sbtest9 | PRIMARY | 142 | 0.002 | 0 | 0.000 | 122 | 0.365 | 16 | 0.097 | | TABLE | sbtest7 | PRIMARY | 142 | 0.002 | 0 | 0.000 | 123 | 0.367 | 15 | 0.087 | +-------------+-------------+------------+---------------------+----------------------+----------------------+-----------------------+----------------------+-----------------------+----------------------+-----------------------+ 20 rows in set (0.002 sec) |
Remark:
If the wait event you had was wait/lock/table/sql/handler in the minimum Performance Schema configuration you can access to table_lock_waits_summary_by_table. The documentation of the columns is not crystal clear to me and I also think that the xxx_READ columns also include the value of xxx_EXTERNAL columns even if the documentation does not specify it. A typical query would look like:
select object_type, object_name, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_read*pow(10,-9),3) as avg_timer_read_msec, round(avg_timer_write*pow(10,-9),3) as avg_timer_write_msec from performance_schema.table_lock_waits_summary_by_table where object_schema = 'sbtest' order by sum_timer_wait desc limit 20; +-------------+-------------+--------------------+---------------------+----------------------+ | object_type | object_name | sum_timer_wait_sec | avg_timer_read_msec | avg_timer_write_msec | +-------------+-------------+--------------------+---------------------+----------------------+ | TABLE | sbtest4 | 2 | 0.001 | 0.001 | | TABLE | sbtest7 | 2 | 0.001 | 0.001 | | TABLE | sbtest17 | 2 | 0.001 | 0.001 | | TABLE | sbtest23 | 2 | 0.001 | 0.001 | | TABLE | sbtest28 | 2 | 0.001 | 0.001 | | TABLE | sbtest16 | 2 | 0.001 | 0.001 | | TABLE | sbtest19 | 2 | 0.001 | 0.001 | | TABLE | sbtest14 | 2 | 0.001 | 0.001 | | TABLE | sbtest10 | 2 | 0.001 | 0.001 | | TABLE | sbtest15 | 2 | 0.001 | 0.001 | | TABLE | sbtest30 | 2 | 0.001 | 0.001 | | TABLE | sbtest25 | 2 | 0.001 | 0.001 | | TABLE | sbtest3 | 2 | 0.001 | 0.001 | | TABLE | sbtest26 | 2 | 0.001 | 0.001 | | TABLE | sbtest11 | 2 | 0.001 | 0.001 | | TABLE | sbtest22 | 2 | 0.001 | 0.001 | | TABLE | sbtest9 | 2 | 0.001 | 0.001 | | TABLE | sbtest2 | 2 | 0.001 | 0.001 | | TABLE | sbtest27 | 2 | 0.001 | 0.001 | | TABLE | sbtest1 | 2 | 0.001 | 0.001 | +-------------+-------------+--------------------+---------------------+----------------------+ |
For memory usage you have access to performance_schema.memory_summary_global_by_event_name table but its content is a bit hard to interpret…
Refer to the official documentation to have the complete list of tables filles with global instrumentation only.
Performance Schema with global and thread instrumentation
With the thread activation you have on top access to all events_xxx_summary_by_yyy_by_event_name, where xxx is waits, stages, statements, transactions; and yyy is thread, user, host, account. The difference between user and account is that account tables also contains the host columns while user tables are aggregated only on user. And the number of new tables is huge as this allows you to dig deeper in objects of your application and SQL queries that are performing the worst…
Between the account and user I rate the user more interesting if you don’t have conections coming from multiple points or if you don’t specifically need to study performance host by host (why would you need to do this by the way ?).
Same host and thread tables are in my opinion less interesting as I would naturally not focus my performance study on per host or on per thread.
My example queries will be so based on user tables.
Wait events of my sysbench user statements:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, sum_lock_time, sum_errors, sum_warnings, sum_rows_affected, sum_rows_sent, sum_rows_examined, sum_created_tmp_disk_tables, sum_created_tmp_tables, sum_select_full_join, sum_select_full_range_join, sum_select_range, sum_select_range_check, sum_select_scan, sum_sort_merge_passes, sum_sort_range, sum_sort_rows, sum_sort_scan, sum_no_index_used, sum_no_good_index_used from performance_schema.events_statements_summary_by_user_by_event_name where user = 'sbuser' order by sum_timer_wait desc limit 10; +-----------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | sum_lock_time | sum_errors | sum_warnings | sum_rows_affected | sum_rows_sent | sum_rows_examined | sum_created_tmp_disk_tables | sum_created_tmp_tables | sum_select_full_join | sum_select_full_range_join | sum_select_range | sum_select_range_check | sum_select_scan | sum_sort_merge_passes | sum_sort_range | sum_sort_rows | sum_sort_scan | sum_no_index_used | sum_no_good_index_used | +-----------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ | statement/sql/select | 70160342 | 14632 | 0.209 | 2072509568000000 | 0 | 0 | 0 | 1558593294 | 3558203340 | 0 | 5011554 | 0 | 0 | 20046216 | 0 | 0 | 0 | 5011453 | 1002290600 | 5011453 | 0 | 0 | | statement/sql/update | 9997758 | 5392 | 0.539 | 375109038000000 | 0 | 0 | 9997758 | 0 | 9997758 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/insert | 4998980 | 1174 | 0.235 | 227068347000000 | 0 | 0 | 5023259 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/delete | 4998980 | 1167 | 0.233 | 142076827000000 | 0 | 0 | 4998980 | 0 | 4998995 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/commit | 5035833 | 1073 | 0.213 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/begin | 5035833 | 167 | 0.033 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/com/Quit | 215 | 0 | 0.009 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/create_index | 0 | 0 | 0.000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/sql/insert_select | 0 | 0 | 0.000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | statement/scheduler/event | 0 | 0 | 0.000 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | +-----------------------------+------------+--------------------+---------------------+------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+ 10 rows in set (0.005 sec) |
Wait events of my sysbench user:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec from performance_schema.events_waits_summary_by_user_by_event_name where user = 'sbuser' order by sum_timer_wait desc limit 10; +------------------------------------------------+------------+--------------------+---------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | +------------------------------------------------+------------+--------------------+---------------------+ | wait/io/table/sql/handler | 2120085693 | 9236 | 0.004 | | idle | 100716876 | 1438 | 0.014 | | wait/io/file/innodb/innodb_data_file | 249970 | 634 | 2.538 | | wait/io/file/sql/binlog | 4758871 | 148 | 0.031 | | wait/lock/table/sql/handler | 90644994 | 57 | 0.001 | | wait/io/file/aria/MAD | 3 | 0 | 14.564 | | wait/io/file/aria/MAI | 9 | 0 | 2.848 | | wait/io/file/sql/binlog_index | 21 | 0 | 0.364 | | wait/lock/metadata/sql/mdl | 0 | 0 | 0.000 | | wait/synch/mutex/sql/MYSQL_BIN_LOG::LOCK_index | 0 | 0 | 0.000 | +------------------------------------------------+------------+--------------------+---------------------+ 10 rows in set (0.006 sec) |
Wait event of my sysbench user transactions:
select event_name, count_star, round(sum_timer_wait*pow(10,-12)) as sum_timer_wait_sec, round(avg_timer_wait*pow(10,-9),3) as avg_timer_wait_msec, count_read_write, round(sum_timer_read_write*pow(10,-12)) as sum_timer_read_write_sec, round(avg_timer_read_write*pow(10,-9),3) as avg_timer_read_write_msec, count_read_only, round(sum_timer_read_only*pow(10,-12)) as sum_timer_read_only_sec, round(avg_timer_read_only*pow(10,-9),3) as avg_timer_read_only_msec from performance_schema.events_transactions_summary_by_user_by_event_name where user = 'sbuser' order by sum_timer_wait desc; +-------------+------------+--------------------+---------------------+------------------+--------------------------+---------------------------+-----------------+-------------------------+--------------------------+ | event_name | count_star | sum_timer_wait_sec | avg_timer_wait_msec | count_read_write | sum_timer_read_write_sec | avg_timer_read_write_msec | count_read_only | sum_timer_read_only_sec | avg_timer_read_only_msec | +-------------+------------+--------------------+---------------------+------------------+--------------------------+---------------------------+-----------------+-------------------------+--------------------------+ | transaction | 1780035 | 8504 | 4.778 | 1780035 | 8504 | 4.778 | 0 | 0 | 0.000 | +-------------+------------+--------------------+---------------------+------------------+--------------------------+---------------------------+-----------------+-------------------------+--------------------------+ 1 row in set (0.001 sec) |
References
- MariaDB Performance Schema
- Chapter 29 MySQL Performance Schema
- Deep Dive into MySQL’s Performance Schema
- MySQL Query Performance Statistics In The Performance Schema
- MARIADB AND MYSQL PERFORMANCE_SCHEMA HINTS
One thought on “Performance schema hands-on – part 1”