Performance schema hands-on – part 2

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. 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 then end of the part 2 of this blog post.

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_schema02
performance_schema02

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

About Post Author

Share the knowledge!

Leave a Reply

Your email address will not be published. Required fields are marked *

You may use these HTML tags and attributes:

<a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>