Table of contents
Preamble
After a first part let’s move forward and activate more options of Performance Schema and go deeper of the analysis of performance.
When activating Performance Schema one of my fear was the performance impact on the application. I know that, with Oracle for example, you (might) have Automatic Workload Repository, Active Session History and SQL monitoring and you do not ask yourself the impact on performance. The benefit it brings in case of problem highly overcome the potential impact it has.
Oracle by the way is constantly communicating that impact is small. For MariaDB/MySQL I have to say that few blog posts find around tend to say that fully activating all the performance counters might not be free of charge for your application… Some like transactions or even worse statements are the more impacting…
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).
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 with global and digest instrumentation
For the Oracle experts around this view is similar from what you would find in V$SQL view. A typical query would be something like, but clearly you should display it in a graphical query tool (HeidiSQL):
select digest, digest_text, 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_lock_time*pow(10,-12)) as sum_lock_time_sec, 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, first_seen, last_seen from performance_schema.events_statements_summary_by_digest where schema_name = 'sbtest' order by sum_timer_wait desc limit 20; +----------------------------------+------------------------------------------+------------+--------------------+---------------------+-------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+ | digest | digest_text | count_star | sum_timer_wait_sec | avg_timer_wait_msec | sum_lock_time_sec | 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 | first_seen | last_seen | +----------------------------------+------------------------------------------+------------+--------------------+---------------------+-------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+ | 92833fb23ce1a1adcd4c2023180cd14e | COMMIT | 5020143 | 1065 | 0.212 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | c5207ac364960bfd3e42a382cf799400 | SELECT `c` FROM `sbtest3` WHERE ID = ? | 1678219 | 251 | 0.149 | 47 | 0 | 0 | 0 | 1678133 | 1678133 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 44c1aa0cd485be9a9c1a74f8425c86b6 | SELECT `c` FROM `sbtest17` WHERE ID = ? | 1670544 | 245 | 0.146 | 47 | 0 | 0 | 0 | 1670413 | 1670413 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 04951846a67f620f8deb11c6dcb71292 | SELECT `c` FROM `sbtest16` WHERE ID = ? | 1675961 | 244 | 0.145 | 48 | 0 | 0 | 0 | 1675887 | 1675885 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 1b54df80b692be695896e3434a4a4045 | SELECT `c` FROM `sbtest6` WHERE ID = ? | 1670079 | 244 | 0.146 | 49 | 0 | 0 | 0 | 1670003 | 1670002 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 95382cdc12745f78be32960b08a2d686 | SELECT `c` FROM `sbtest7` WHERE ID = ? | 1675290 | 243 | 0.145 | 48 | 0 | 0 | 0 | 1675229 | 1675226 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 0ef010065490cba557ea79df8936ebaa | SELECT `c` FROM `sbtest4` WHERE ID = ? | 1679153 | 242 | 0.144 | 48 | 0 | 0 | 0 | 1679095 | 1679094 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 41cb8efd10f9923d889999d2c537430c | SELECT `c` FROM `sbtest10` WHERE ID = ? | 1674875 | 242 | 0.145 | 48 | 0 | 0 | 0 | 1674822 | 1674820 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 6915e6ac3566ae2e8698a97040752919 | SELECT `c` FROM `sbtest30` WHERE ID = ? | 1684439 | 242 | 0.143 | 48 | 0 | 0 | 0 | 1684356 | 1684355 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 300ec9582fd2cbab2e275876d60dbe3a | SELECT `c` FROM `sbtest23` WHERE ID = ? | 1683107 | 242 | 0.144 | 48 | 0 | 0 | 0 | 1682996 | 1682998 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | a20a902d4f263ab990929c1893ce0673 | SELECT `c` FROM `sbtest14` WHERE ID = ? | 1676838 | 241 | 0.144 | 47 | 0 | 0 | 0 | 1676753 | 1676749 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | dffdf6919eb780817906482ec8761c53 | SELECT `c` FROM `sbtest9` WHERE ID = ? | 1673539 | 241 | 0.144 | 48 | 0 | 0 | 0 | 1673497 | 1673498 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 84081f8486e19e48f6519e97fd71648b | SELECT `c` FROM `sbtest15` WHERE ID = ? | 1673746 | 241 | 0.144 | 48 | 0 | 0 | 0 | 1673657 | 1673658 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 9a603a748e3692a2dbb8d1c4a11ecdaf | SELECT `c` FROM `sbtest5` WHERE ID = ? | 1670223 | 240 | 0.144 | 47 | 0 | 0 | 0 | 1670181 | 1670182 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 2208a7f6f6192540abb67cf4404b3ae1 | SELECT `c` FROM `sbtest20` WHERE ID = ? | 1664129 | 240 | 0.144 | 47 | 0 | 0 | 0 | 1664046 | 1664046 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | f30eb04184e0a4e1f620774cd74d6736 | SELECT `c` FROM `sbtest29` WHERE ID = ? | 1675862 | 240 | 0.143 | 47 | 0 | 0 | 0 | 1675800 | 1675796 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | a292d16292a4907416f01f5f7f8e1e27 | SELECT `c` FROM `sbtest2` WHERE ID = ? | 1665622 | 240 | 0.144 | 47 | 0 | 0 | 0 | 1665539 | 1665539 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | e59530b9a46ab060c8a2c2a1849b7c3a | SELECT `c` FROM `sbtest11` WHERE ID = ? | 1678382 | 239 | 0.143 | 48 | 0 | 0 | 0 | 1678317 | 1678314 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | 7ae1f16d0f40c42e37fb79ed6a4c2256 | SELECT `c` FROM `sbtest18` WHERE ID = ? | 1671365 | 239 | 0.143 | 47 | 0 | 0 | 0 | 1671296 | 1671296 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | | cb7a20ef0f204cd8538a379f02641d9a | SELECT `c` FROM `sbtest27` WHERE ID = ? | 1668454 | 239 | 0.143 | 47 | 0 | 0 | 0 | 1668363 | 1668362 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 2024-01-31 10:34:50 | 2024-01-31 12:21:56 | +----------------------------------+------------------------------------------+------------+--------------------+---------------------+-------------------+------------+--------------+-------------------+---------------+-------------------+-----------------------------+------------------------+----------------------+----------------------------+------------------+------------------------+-----------------+-----------------------+----------------+---------------+---------------+-------------------+------------------------+---------------------+---------------------+ 20 rows in set (0.005 sec) |
With HeidiSQL it gives:
Performance Schema with global, thread and current event instrumentation
To activate current event instrumentation do:
MariaDB [(none)]> update performance_schema.setup_consumers set enabled='YES' where name like '%current'; Query OK, 4 rows affected (0.000 sec) Rows matched: 4 Changed: 4 Warnings: 0 MariaDB [(none)]> select * from performance_schema.setup_consumers order by name; +----------------------------------+---------+ | NAME | ENABLED | +----------------------------------+---------+ | events_stages_current | YES | | events_stages_history | NO | | events_stages_history_long | NO | | events_statements_current | YES | | events_statements_history | NO | | events_statements_history_long | NO | | events_transactions_current | YES | | events_transactions_history | NO | | events_transactions_history_long | NO | | events_waits_current | YES | | events_waits_history | NO | | events_waits_history_long | NO | | global_instrumentation | YES | | statements_digest | YES | | thread_instrumentation | YES | +----------------------------------+---------+ 15 rows in set (0.001 sec) |
Updating the performance_schema.setup_consumers does not resist of a bounce of the instance, to make it persistent add to your my.cnf:
performance-schema-consumer-events-stages-current=ON performance-schema-consumer-events-statements-current=ON performance-schema-consumer-events-transactions-current=ON performance-schema-consumer-events-waits-current=ON |
The current tables are an instant snapshot of the activity of your instance so you need to execute your queries while sysbench is running (or when you have your applicative workload). Due to the low instrumentation activated for stages the performance_schema.events_stages_current has nothing to display.
The global current wait events:
select thread_id, -- event_id, -- end_event_id, event_name, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, spins, object_schema, object_name, index_name, object_type, -- object_instance_begin, -- nesting_event_id, -- nesting_event_type, operation -- number_of_bytes, -- flags from performance_schema.events_waits_current where event_name<>'idle' order by timer_wait desc limit 20; +-----------+--------------------------------------+-----------------+-------+---------------+------------------------------------------------+------------+-------------+-----------+ | thread_id | event_name | timer_wait_msec | spins | object_schema | object_name | index_name | object_type | operation | +-----------+--------------------------------------+-----------------+-------+---------------+------------------------------------------------+------------+-------------+-----------+ | 98 | wait/io/file/sql/binlog | 8 | NULL | NULL | /mariadb/logs/mariadb01/mariadb-bin.000039 | NULL | FILE | write | | 101 | wait/io/table/sql/handler | 8 | NULL | sbtest | sbtest26 | PRIMARY | TABLE | fetch | | 95 | wait/io/table/sql/handler | 7 | NULL | sbtest | sbtest3 | NULL | TABLE | insert | | 89 | wait/io/table/sql/handler | 6 | NULL | sbtest | sbtest14 | PRIMARY | TABLE | update | | 108 | wait/io/file/innodb/innodb_data_file | 1 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest25.ibd | NULL | FILE | write | | 105 | wait/io/file/innodb/innodb_data_file | 1 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest13.ibd | NULL | FILE | write | | 112 | wait/io/file/innodb/innodb_data_file | 1 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest18.ibd | NULL | FILE | read | | 107 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest21.ibd | NULL | FILE | write | | 103 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest9.ibd | NULL | FILE | write | | 8 | wait/io/file/sql/pid | 0 | NULL | NULL | /mariadb/software/mariadb01/conf/mariadb01.pid | NULL | FILE | close | | 4 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/ibdata1 | NULL | FILE | write | | 110 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest20.ibd | NULL | FILE | write | | 119 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest7.ibd | NULL | FILE | write | | 7 | wait/io/file/sql/binlog | 0 | NULL | NULL | /mariadb/logs/mariadb01/mariadb-bin.000039 | NULL | FILE | write | | 104 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest27.ibd | NULL | FILE | write | | 1 | wait/io/file/aria/MAD | 0 | NULL | NULL | /mariadb/data01/mariadb01/mysql/event.MAD | NULL | FILE | read | | 114 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest14.ibd | NULL | FILE | write | | 111 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest29.ibd | NULL | FILE | write | | 115 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest28.ibd | NULL | FILE | write | | 106 | wait/io/file/innodb/innodb_data_file | 0 | NULL | NULL | /mariadb/data01/mariadb01/sbtest/sbtest25.ibd | NULL | FILE | sync | +-----------+--------------------------------------+-----------------+-------+---------------+------------------------------------------------+------------+-------------+-----------+ 20 rows in set (0.001 sec) |
The current statements wait events:
select thread_id, -- event_id, -- end_event_id event_name, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, lock_time, -- sql_text, -- digest, digest_text, -- current_schema, -- object_type, -- object_schema, -- object_name, -- object_instance_begin, -- mysql_errno, -- returned_sqlstate, -- message_text, errors, warnings, rows_affected, rows_sent, rows_examined, created_tmp_disk_tables, created_tmp_tables, select_full_join, select_full_range_join, select_range, select_range_check, select_scan, sort_merge_passes, sort_range, sort_rows, sort_scan, no_index_used, no_good_index_used -- nesting_event_id, -- nesting_event_type, -- nesting_event_level from performance_schema.events_statements_current where current_schema = 'sbtest' order by timer_wait desc limit 10; +-----------+-------------------------------+-----------------+-----------+-------------------------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ | thread_id | event_name | timer_wait_msec | lock_time | digest_text | errors | warnings | rows_affected | rows_sent | rows_examined | created_tmp_disk_tables | created_tmp_tables | select_full_join | select_full_range_join | select_range | select_range_check | select_scan | sort_merge_passes | sort_range | sort_rows | sort_scan | no_index_used | no_good_index_used | +-----------+-------------------------------+-----------------+-----------+-------------------------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ | 208 | statement/sql/delete | 5 | 54000000 | NULL | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 199 | statement/sql/select | 1 | 54000000 | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 200 | statement/sql/update | 0 | 0 | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 198 | statement/sql/select | 0 | 57000000 | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 218 | statement/sql/select | 1 | 58000000 | NULL | 0 | 0 | 0 | 99 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 1 | 100 | 0 | 0 | 0 | | 210 | statement/sql/select | 1 | 58000000 | SELECT `c` FROM `sbtest24` WHERE ID BETWEEN ? AND ? ORDER BY `c` | 0 | 0 | 0 | 100 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 1 | 100 | 0 | 0 | 0 | | 203 | statement/abstract/new_packet | 0 | 0 | NULL | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 220 | statement/sql/select | 0 | 61000000 | SELECT SUM ( `K` ) FROM `sbtest14` WHERE ID BETWEEN ? AND ? | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 212 | statement/sql/select | 0 | 52000000 | SELECT `c` FROM `sbtest24` WHERE ID = ? | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 207 | statement/sql/select | 0 | 65000000 | SELECT `c` FROM `sbtest27` WHERE ID = ? | 0 | 0 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | +-----------+-------------------------------+-----------------+-----------+-------------------------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ 10 rows in set (0.001 sec) |
The current statement wait events:
select thread_id, -- event_id, -- end_event_id, event_name, state, -- trx_id, -- gtid, -- xid_format_id, -- xid_gtrid, -- xid_bqual, -- xa_state, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, access_mode, isolation_level, autocommit, number_of_savepoints, number_of_rollback_to_savepoint, number_of_release_savepoint, object_instance_begin, nesting_event_id, nesting_event_type from performance_schema.events_transactions_current order by timer_wait desc limit 10; +-----------+-------------+--------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ | thread_id | event_name | state | timer_wait_msec | access_mode | isolation_level | autocommit | number_of_savepoints | number_of_rollback_to_savepoint | number_of_release_savepoint | object_instance_begin | nesting_event_id | nesting_event_type | +-----------+-------------+--------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ | 198 | transaction | ACTIVE | 477 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1592537 | STATEMENT | | 219 | transaction | ACTIVE | 474 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1541564 | STATEMENT | | 203 | transaction | ACTIVE | 474 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1511993 | STATEMENT | | 202 | transaction | ACTIVE | 473 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1554100 | STATEMENT | | 208 | transaction | ACTIVE | 473 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1533669 | STATEMENT | | 206 | transaction | ACTIVE | 473 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1545655 | STATEMENT | | 205 | transaction | ACTIVE | 472 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1550052 | STATEMENT | | 215 | transaction | ACTIVE | 472 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1581673 | STATEMENT | | 207 | transaction | ACTIVE | 471 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1532314 | STATEMENT | | 212 | transaction | ACTIVE | 470 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 1573706 | STATEMENT | +-----------+-------------+--------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ 10 rows in set (0.001 sec) |
Remark:
In real life it is difficult to really benefit from those tables as you must be there when the performance problem occur and the rows might gone when you are working on them trying to understand what the problem is… So let’s move forward quickly to history tables in next chapter.
Performance Schema with global, thread and event history instrumentation
It is not so easy to understand the difference between events_xxx_history and events_xxx_history_long tables. From official documentation:
- events_xxx_history: The “recent history” table stores the most recent events that have ended per thread (up to a maximum number of rows per thread). events_xxx_history is meant to investigate individual threads, independently of the global server load.
- events_xxx_history_long: The “long history” table stores the most recent events that have ended globally (across all threads, up to a maximum number of rows per table). events_xxx_history_long is meant to investigate the server globally, not each thread. events_xxx_history_long have no indexing.
For the type of analysis I have the habit to do I have a personal preference for the events_xxx_history_long. The queries on both type of tables are exactly the same as the tables have exactly the same columns. The events_xxx_history_long have longer history by default (can be changed):
MariaDB [(none)]> show variables like 'performance%history%'; +----------------------------------------------------------+-------+ | Variable_name | Value | +----------------------------------------------------------+-------+ | performance_schema_events_stages_history_long_size | 1000 | | performance_schema_events_stages_history_size | 10 | | performance_schema_events_statements_history_long_size | 1000 | | performance_schema_events_statements_history_size | 10 | | performance_schema_events_transactions_history_long_size | 1000 | | performance_schema_events_transactions_history_size | 10 | | performance_schema_events_waits_history_long_size | 1000 | | performance_schema_events_waits_history_size | 10 | +----------------------------------------------------------+-------+ 8 rows in set (0.001 sec) |
To activate the events_xxx_history Performance Schema tables do:
MariaDB [(none)]> update performance_schema.setup_consumers set enabled='YES' where name like '%history'; Query OK, 4 rows affected (0.000 sec) Rows matched: 4 Changed: 4 Warnings: 0 |
To activate events_xxx_history_long Performance Schema tables:
MariaDB [(none)]> update performance_schema.setup_consumers set enabled='YES' where name like '%history_long'; Query OK, 4 rows affected (0.000 sec) Rows matched: 4 Changed: 4 Warnings: 0 MariaDB [(none)]> select * from performance_schema.setup_consumers order by name; +----------------------------------+---------+ | NAME | ENABLED | +----------------------------------+---------+ | events_stages_current | YES | | events_stages_history | NO | | events_stages_history_long | YES | | events_statements_current | YES | | events_statements_history | NO | | events_statements_history_long | YES | | events_transactions_current | YES | | events_transactions_history | NO | | events_transactions_history_long | YES | | events_waits_current | YES | | events_waits_history | NO | | events_waits_history_long | YES | | global_instrumentation | YES | | statements_digest | YES | | thread_instrumentation | YES | +----------------------------------+---------+ 15 rows in set (0.001 sec) |
Updating the performance_schema.setup_consumers does not resist of a bounce of the instance, to make it persistent add to your my.cnf:
performance-schema-consumer-events-stages-history-long=ON performance-schema-consumer-events-statements-history-long=ON performance-schema-consumer-events-transactions-history-long=ON performance-schema-consumer-events-waits-history-long=ON |
Global wait events history long:
select thread_id, -- event_id, -- end_event_id, event_name, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, spins, object_schema, object_name, index_name, object_type, -- object_instance_begin, -- nesting_event_id, -- nesting_event_type, operation -- number_of_bytes, -- flags from performance_schema.events_waits_history_long where event_name <> 'idle' order by timer_wait desc limit 20; +-----------+-----------------------+-----------------+-------+---------------+--------------------------------------+------------+-------------+-----------+ | thread_id | event_name | timer_wait_msec | spins | object_schema | object_name | index_name | object_type | operation | +-----------+-----------------------+-----------------+-------+---------------+--------------------------------------+------------+-------------+-----------+ | 14 | wait/io/file/aria/MAD | 10 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAD | NULL | FILE | open | | 14 | wait/io/file/aria/MAI | 9 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAI | NULL | FILE | open | | 14 | wait/io/file/aria/MAI | 8 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAI | NULL | FILE | open | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAI | NULL | FILE | create | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367d.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367d.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367c.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAD | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAD | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367f.MAI | NULL | FILE | delete | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367c.MAI | NULL | FILE | close | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAI | NULL | FILE | create | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-367d.MAI | NULL | FILE | delete | | 14 | wait/io/file/aria/MAI | 0 | NULL | NULL | /tmp/#sql-temptable-551b9-4-3680.MAI | NULL | FILE | delete | +-----------+-----------------------+-----------------+-------+---------------+--------------------------------------+------------+-------------+-----------+ 20 rows in set (0.002 sec) |
Transactions wait events history long:
select thread_id, -- event_id, -- end_event_id, event_name, state, -- trx_id, -- gtid, -- xid_format_id, -- xid_gtrid, -- xid_bqual, -- xa_state, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, access_mode, isolation_level, autocommit, number_of_savepoints, number_of_rollback_to_savepoint, number_of_release_savepoint, object_instance_begin, nesting_event_id, nesting_event_type from performance_schema.events_transactions_history_long order by timer_wait desc limit 10; +-----------+-------------+-----------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ | thread_id | event_name | state | timer_wait_msec | access_mode | isolation_level | autocommit | number_of_savepoints | number_of_rollback_to_savepoint | number_of_release_savepoint | object_instance_begin | nesting_event_id | nesting_event_type | +-----------+-------------+-----------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ | 898 | transaction | COMMITTED | 587 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3377484 | STATEMENT | | 897 | transaction | COMMITTED | 253 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3380846 | STATEMENT | | 880 | transaction | COMMITTED | 168 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3347390 | STATEMENT | | 885 | transaction | COMMITTED | 168 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3379394 | STATEMENT | | 893 | transaction | COMMITTED | 167 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3385045 | STATEMENT | | 879 | transaction | COMMITTED | 167 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3358094 | STATEMENT | | 886 | transaction | COMMITTED | 166 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3359469 | STATEMENT | | 892 | transaction | COMMITTED | 166 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3356640 | STATEMENT | | 896 | transaction | COMMITTED | 166 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3330773 | STATEMENT | | 882 | transaction | COMMITTED | 166 | READ WRITE | REPEATABLE READ | NO | 0 | 0 | 0 | NULL | 3362898 | STATEMENT | +-----------+-------------+-----------+-----------------+-------------+-----------------+------------+----------------------+---------------------------------+-----------------------------+-----------------------+------------------+--------------------+ 10 rows in set (0.003 sec) |
Statements wait events history long:
select thread_id, -- event_id, -- end_event_id event_name, -- source, -- timer_start, -- timer_end, round(timer_wait*pow(10,-9)) as timer_wait_msec, lock_time, -- sql_text, -- digest, digest_text, -- current_schema, -- object_type, -- object_schema, -- object_name, -- object_instance_begin, -- mysql_errno, -- returned_sqlstate, -- message_text, errors, warnings, rows_affected, rows_sent, rows_examined, created_tmp_disk_tables, created_tmp_tables, select_full_join, select_full_range_join, select_range, select_range_check, select_scan, sort_merge_passes, sort_range, sort_rows, sort_scan, no_index_used, no_good_index_used -- nesting_event_id, -- nesting_event_type, -- nesting_event_level from performance_schema.events_statements_history_long where current_schema = 'sbtest' order by timer_wait desc limit 10; +-----------+----------------------+-----------------+-----------+---------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ | thread_id | event_name | timer_wait_msec | lock_time | digest_text | errors | warnings | rows_affected | rows_sent | rows_examined | created_tmp_disk_tables | created_tmp_tables | select_full_join | select_full_range_join | select_range | select_range_check | select_scan | sort_merge_passes | sort_range | sort_rows | sort_scan | no_index_used | no_good_index_used | +-----------+----------------------+-----------------+-----------+---------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ | 897 | statement/sql/update | 248 | 54000000 | UPDATE `sbtest22` SET `c` = ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 893 | statement/sql/update | 163 | 41000000 | UPDATE `sbtest18` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 885 | statement/sql/update | 163 | 57000000 | UPDATE `sbtest25` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 879 | statement/sql/update | 162 | 46000000 | UPDATE `sbtest16` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 886 | statement/sql/update | 162 | 31000000 | UPDATE `sbtest20` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 896 | statement/sql/update | 161 | 46000000 | UPDATE `sbtest19` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 882 | statement/sql/update | 161 | 43000000 | UPDATE `sbtest2` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 880 | statement/sql/update | 161 | 56000000 | UPDATE `sbtest8` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 887 | statement/sql/update | 161 | 26000000 | UPDATE `sbtest30` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | | 895 | statement/sql/update | 161 | 40000000 | UPDATE `sbtest3` SET `k` = `k` + ? WHERE ID = ? | 0 | 0 | 1 | 0 | 1 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | 0 | +-----------+----------------------+-----------------+-----------+---------------------------------------------------+--------+----------+---------------+-----------+---------------+-------------------------+--------------------+------------------+------------------------+--------------+--------------------+-------------+-------------------+------------+-----------+-----------+---------------+--------------------+ 10 rows in set (0.007 sec) |
Performance Schema impact
The command to prepare the sysbench data model I have used is (around 10GB of data):
sysbench --db-driver=mysql --oltp-tables-count=30 --oltp-table-size=1000000 /usr/share/sysbench/tests/include/oltp_legacy/oltp.lua --mysql-host=localhost \ --mysql-socket=/mariadb/software/mariadb01/conf/mariadb01.sock --mysql-user=sbuser --mysql-password=secret_password prepare |
Then I issued below sysbench command:
sysbench --db-driver=mysql --threads=24 --events=1000000 --oltp-tables-count=30 --oltp-table-size=1000000 --oltp-test-mode=complex --oltp-dist-type=uniform \ /usr/share/sysbench/tests/include/oltp_legacy/oltp.lua --mysql-host=localhost --mysql-socket=/mariadb/software/mariadb01/conf/mariadb01.sock \ --mysql-user=sbuser --mysql-password=secret_password --time=120 --report-interval=10 run |
After a warm up I have issued multiple runs and I was around 4800-4900 transactions per second.
I have activated Performance Schema current and history event instrumentation for stages, statements, transactions and waits as well as the instrumentation on transaction to enabled and timed the instrument. Global, thread and digest instrumentation are activated by default in my MariaDB 10.11.6 Community Edition version. I have then re-perform a bunch of sysbench command to see if I had a decrease of performance.
The good news is that with my additional activation I did not encounter any performance decrease over the multiple sysbench runs I have executed. So the promise of minimal impact was true ! Of course it could be different for another workload.
It could also be a complete different story if you activate more setup_consumers and obviously more setup_instruments. So always be careful when playing with those options…
References
One thought on “Performance schema hands-on – part 2”