MariaDB 10.5 added a lot of instrumentation around stored procedures, functions and events along the lines of MySQL WL#5766. In this blog post I'll try to check how it works and provide some details that are still missing in the MariaDB Knowledge Base.
So, in frames of porting most of Performance Schema from MySQL 5.7 to MariaDB 10.5 four new types of Performance Schema objects were added:
MariaDB [performance_schema]> select distinct(object_type) from setup_objects;
+-------------+
| object_type |
+-------------+
| EVENT |
| FUNCTION |
| PROCEDURE |
| TABLE |
| TRIGGER |
+-------------+
5 rows in set (0,001 sec)
MariaDB [performance_schema]> select * from setup_objects where object_type != 'TABLE' and object_schema not in ('mysql', 'performance_schema', 'information_schema');
+-------------+---------------+-------------+---------+-------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | ENABLED | TIMED |
+-------------+---------------+-------------+---------+-------+
| EVENT | % | % | YES | YES |
| FUNCTION | % | % | YES | YES |
| PROCEDURE | % | % | YES | YES |
| TRIGGER | % | % | YES | YES |
+-------------+---------------+-------------+---------+-------+
4 rows in set (0,001 sec)
MariaDB [performance_schema]> select version();
+----------------+
| version() |
+----------------+
| 10.5.7-MariaDB |
+----------------+
1 row in set (0,000 sec)
As you can see from the above, these objects are enabled and timed by default in all databases besides system ones. Additional 20 instruments were also added, enabled and timed by default:
MariaDB [performance_schema]> select * from setup_instruments where name like 'statement/sp/%' or name like 'statement/scheduler%';
+---------------------------------+---------+-------+
| NAME | ENABLED | TIMED |
+---------------------------------+---------+-------+
| statement/sp/stmt | YES | YES |
| statement/sp/set | YES | YES |
| statement/sp/set_trigger_field | YES | YES |
| statement/sp/jump | YES | YES |
| statement/sp/jump_if_not | YES | YES |
| statement/sp/freturn | YES | YES |
| statement/sp/preturn | YES | YES |
| statement/sp/hpush_jump | YES | YES |
| statement/sp/hpop | YES | YES |
| statement/sp/hreturn | YES | YES |
| statement/sp/cpush | YES | YES |
| statement/sp/cpop | YES | YES |
| statement/sp/copen | YES | YES |
| statement/sp/cclose | YES | YES |
| statement/sp/cfetch | YES | YES |
| statement/sp/agg_cfetch | YES | YES |
| statement/sp/cursor_copy_struct | YES | YES |
| statement/sp/error | YES | YES |
| statement/sp/set_case_expr | YES | YES |
| statement/scheduler/event | YES | YES |
+---------------------------------+---------+-------+
20 rows in set (0,002 sec)
In the above I do not see any direct match to most of statements used in stored procedures. You may be wondering what statement/sp/jump_if_not is, for example. These instruments are representing instructions of the low level sp_instr language used to implement the semantics of flow control statements and exception handlers. See more details about them in the MySQL Source Code documentation. As I use a non-debug build, attempt to see these instructions from the procedure using SHOW PROCEDURE CODE statement surely failed:
MariaDB [performance_schema]> show procedure code sbtest.p_sbtest1;
ERROR 1289 (HY000): The 'SHOW PROCEDURE|FUNCTION CODE' feature is disabled; you need MariaDB built with '--with-debug' to have it working
The statement/sp/stmt instrument represents usual DDL or DML statement that is executed "as is".
To check how these new instrument work I deci8ded to add a trigger calling a primitive stored procedure to the table created by sysbench:
MariaDB [sbtest]> show create table sbtest1\G
*************************** 1. row ***************************
Table: sbtest1
Create Table: CREATE TABLE `sbtest1` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`k` int(11) NOT NULL DEFAULT 0,
`c` char(120) NOT NULL DEFAULT '',
`pad` char(60) NOT NULL DEFAULT '',
PRIMARY KEY (`id`),
KEY `k_1` (`k`)
) ENGINE=InnoDB AUTO_INCREMENT=1000001 DEFAULT CHARSET=latin1
1 row in set (0,001 sec)
MariaDB [sbtest]> set sql_mode='ORACLE';
Query OK, 0 rows affected (0,000 sec)
MariaDB [sbtest]> delimiter //
MariaDB [sbtest]> create procedure p_sbtest1(id int) as begin select k into @k from sbtest1 t where t.id = id; set @i := 0; for i in 1..round(@k/1000)+1 loop set @i := @i + 1; end loop; end;//
Query OK, 0 rows affected (0,058 sec)
MariaDB [sbtest]> create trigger tr1 after update on sbtest1 for each row call p_sbtest1(new.id);//
Query OK, 0 rows affected (0,086 sec)
MariaDB [sbtest]> delimiter ;
This is a primitive procedure that runs some loop to add delay. For fun I've used ORACLE mode and for loop inherited from PL/SQL that is really nice.
With all these in place I ran the following simple sysbench oltp_update_index.lua test for 50 seconds:
openxs@ao756:~/dbs/maria10.5$ sysbench --table-size=1000000 --threads=4 --time=50 --mysql-socket=/tmp/mariadb105.sock --mysql-user=openxs --mysql-db=sbtest --report-interval=5 /usr/share/sysbench/oltp_update_index.lua run
sysbench 1.1.0-faaff4f (using bundled LuaJIT 2.1.0-beta3)
Running the test with following options:
Number of threads: 4
Report intermediate results every 5 second(s)
Initializing random number generator from current time
Initializing worker threads...
Threads started!
[ 5s ] thds: 4 tps: 130.61 qps: 130.61 (r/w/o: 0.00/130.61/0.00) lat (ms,95%): 55.82 err/s: 0.00 reconn/s: 0.00
...
and while it was running checked current stored procedure-related statements multiple times with the following SELECT:
MariaDB [performance_schema]> select * from events_statements_current where event_name like 'statement/sp/%'\G
Empty set (0,001 sec)
In all cases I've got zero rows. That's because related consumer is not enabled by default:
MariaDB [performance_schema]> select * from setup_consumers;
+----------------------------------+---------+
| NAME | ENABLED |
+----------------------------------+---------+
| events_stages_current | NO |
| events_stages_history | NO |
| events_stages_history_long | NO |
| events_statements_current | NO |
| events_statements_history | NO |
| events_statements_history_long | NO |
| events_transactions_current | NO |
| events_transactions_history | NO |
| events_transactions_history_long | NO |
| events_waits_current | NO |
| events_waits_history | NO |
| events_waits_history_long | NO |
| global_instrumentation | YES |
| thread_instrumentation | YES |
| statements_digest | YES |
+----------------------------------+---------+
15 rows in set (0,001 sec)
I've enables all of them with update setup_consumers set enabled = 'YES'; and retried the test:
MariaDB [performance_schema]> select * from events_statements_current where event_name like 'statement/sp/%'\G
...
*************************** 2. row ***************************
THREAD_ID: 54
EVENT_ID: 1375298
END_EVENT_ID: NULL
EVENT_NAME: statement/sp/set
SOURCE:
TIMER_START: 1751798753952000
TIMER_END: 1751800198407000
TIMER_WAIT: 1444455000
LOCK_TIME: 0
SQL_TEXT: NULL
DIGEST: NULL
DIGEST_TEXT: NULL
CURRENT_SCHEMA: sbtest
OBJECT_TYPE: PROCEDURE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: p_sbtest1
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
...
NESTING_EVENT_ID: 1373590
NESTING_EVENT_TYPE: STATEMENT
NESTING_EVENT_LEVEL: 2
*************************** 3. row ***************************
THREAD_ID: 56
EVENT_ID: 1335724
END_EVENT_ID: NULL
EVENT_NAME: statement/sp/stmt
SOURCE:
TIMER_START: 1751791595187000
TIMER_END: 1751800213219000
TIMER_WAIT: 8618032000
LOCK_TIME: 0
SQL_TEXT: call p_sbtest1(new.id)
DIGEST: NULL
DIGEST_TEXT: NULL
CURRENT_SCHEMA: sbtest
OBJECT_TYPE: TRIGGER
OBJECT_SCHEMA: sbtest
OBJECT_NAME: tr1
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
...
NESTING_EVENT_ID: 1335719
NESTING_EVENT_TYPE: STATEMENT
NESTING_EVENT_LEVEL: 1
*************************** 4. row ***************************
THREAD_ID: 56
EVENT_ID: 1337567
END_EVENT_ID: NULL
EVENT_NAME: statement/sp/stmt
SOURCE:
TIMER_START: 1751799809228000
TIMER_END: 1751800221029000
TIMER_WAIT: 411801000
LOCK_TIME: 0
SQL_TEXT: SET @i := @i + 1
DIGEST: NULL
DIGEST_TEXT: NULL
CURRENT_SCHEMA: sbtest
OBJECT_TYPE: PROCEDURE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: p_sbtest1
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: NULL
MESSAGE_TEXT: NULL
ERRORS: 0
...
NESTING_EVENT_ID: 1335724
NESTING_EVENT_TYPE: STATEMENT
NESTING_EVENT_LEVEL: 2
...
*************************** 6. row ***************************
THREAD_ID: 57
EVENT_ID: 1342865
END_EVENT_ID: NULL
EVENT_NAME: statement/sp/jump_if_not
SOURCE:
TIMER_START: 1751800236059000
TIMER_END: 1751800238311000
TIMER_WAIT: 2252000
LOCK_TIME: 0
SQL_TEXT: NULL
DIGEST: NULL
DIGEST_TEXT: NULL
CURRENT_SCHEMA: sbtest
OBJECT_TYPE: PROCEDURE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: p_sbtest1
OBJECT_INSTANCE_BEGIN: NULL
MYSQL_ERRNO: 0
RETURNED_SQLSTATE: NULL
MESSAGE_TEXT: NULL
ERRORS: 0
WARNINGS: 0
ROWS_AFFECTED: 0
ROWS_SENT: 0
ROWS_EXAMINED: 0
CREATED_TMP_DISK_TABLES: 0
CREATED_TMP_TABLES: 0
SELECT_FULL_JOIN: 0
SELECT_FULL_RANGE_JOIN: 0
SELECT_RANGE: 0
SELECT_RANGE_CHECK: 0
SELECT_SCAN: 0
SORT_MERGE_PASSES: 0
SORT_RANGE: 0
SORT_ROWS: 0
SORT_SCAN: 0
NO_INDEX_USED: 0
NO_GOOD_INDEX_USED: 0
NESTING_EVENT_ID: 1342859
NESTING_EVENT_TYPE: STATEMENT
NESTING_EVENT_LEVEL: 2
6 rows in set (0,001 sec)
I highlighted some of the interesting column values above. We see SOURCE is always empty (like in MDEV-23827 I've reported while working on the previous post). Looks like this is a common problem for all kinds of instrumentation and I suspect it may have something to do with compile time adding of PSI keys discussed in MDEV-22841. We also see statements from both trigger and procedure, with different NESTING_EVENT_LEVEL. So, basically this new instrumentation work, even though on non-debug builds matching the stored procedure statements reported to flow control statements may become non-trivial. Let's hope most of the time spent is actually spent on nested DML and DDL statements and not on flow control itself.
Additionally there is a new summary table, events_statements_summary_by_program:
MariaDB [performance_schema]> select * from events_statements_summary_by_program\G
*************************** 1. row ***************************
OBJECT_TYPE: TRIGGER
OBJECT_SCHEMA: sbtest
OBJECT_NAME: tr1
COUNT_STAR: 16858
SUM_TIMER_WAIT: 171716322309000
MIN_TIMER_WAIT: 0
AVG_TIMER_WAIT: 10186043000
MAX_TIMER_WAIT: 69867594000
COUNT_STATEMENTS: 9193
SUM_STATEMENTS_WAIT: 107504946033000
MIN_STATEMENTS_WAIT: 4378538000
AVG_STATEMENTS_WAIT: 11694217000
MAX_STATEMENTS_WAIT: 69849730000
SUM_LOCK_TIME: 0
SUM_ERRORS: 0
SUM_WARNINGS: 0
SUM_ROWS_AFFECTED: 0
SUM_ROWS_SENT: 0
SUM_ROWS_EXAMINED: 0
SUM_CREATED_TMP_DISK_TABLES: 0
SUM_CREATED_TMP_TABLES: 0
SUM_SELECT_FULL_JOIN: 0
SUM_SELECT_FULL_RANGE_JOIN: 0
SUM_SELECT_RANGE: 0
SUM_SELECT_RANGE_CHECK: 0
SUM_SELECT_SCAN: 0
SUM_SORT_MERGE_PASSES: 0
SUM_SORT_RANGE: 0
SUM_SORT_ROWS: 0
SUM_SORT_SCAN: 0
SUM_NO_INDEX_USED: 0
SUM_NO_GOOD_INDEX_USED: 0
*************************** 2. row ***************************
OBJECT_TYPE: PROCEDURE
OBJECT_SCHEMA: sbtest
OBJECT_NAME: p_sbtest1
COUNT_STAR: 16858
SUM_TIMER_WAIT: 170865294923000
MIN_TIMER_WAIT: 0
AVG_TIMER_WAIT: 10135561000
MAX_TIMER_WAIT: 69774831000
COUNT_STATEMENTS: 18368282
SUM_STATEMENTS_WAIT: 70946124125000
MIN_STATEMENTS_WAIT: 112000
AVG_STATEMENTS_WAIT: 3862000
MAX_STATEMENTS_WAIT: 26757028000
SUM_LOCK_TIME: 0
SUM_ERRORS: 0
SUM_WARNINGS: 0
SUM_ROWS_AFFECTED: 0
SUM_ROWS_SENT: 0
SUM_ROWS_EXAMINED: 8686
SUM_CREATED_TMP_DISK_TABLES: 0
SUM_CREATED_TMP_TABLES: 0
SUM_SELECT_FULL_JOIN: 0
SUM_SELECT_FULL_RANGE_JOIN: 0
SUM_SELECT_RANGE: 0
SUM_SELECT_RANGE_CHECK: 0
SUM_SELECT_SCAN: 0
SUM_SORT_MERGE_PASSES: 0
SUM_SORT_RANGE: 0
SUM_SORT_ROWS: 0
SUM_SORT_SCAN: 0
SUM_NO_INDEX_USED: 0
SUM_NO_GOOD_INDEX_USED: 0
2 rows in set (0,001 sec)
and there we have the entire new section of 4 columns:
SUM_STATEMENTS_WAIT: 70946124125000
MIN_STATEMENTS_WAIT: 112000
AVG_STATEMENTS_WAIT: 3862000
MAX_STATEMENTS_WAIT: 26757028000
for time spent on executing individual statements within procedure or trigger. We can subtract SUM_STATEMENTS_WAIT from SUM_WAIT to find out how much time was spent on "flow control" overhead inside the stored procedure.
 |
| We now have more insights into the internal working of all this machinery... |
To summarize, MariaDB 10.5, among other things, added instrumentation for stored procedures, functions, triggers and events. It is enabled by default for all non-system databases and is ready to use if you enable related consumers. I hope lack of official documentation at the moment will not prevent users from checking most time consuming stored program units and details of their internal work via Performance Schema. They may easily find out that they are actually bad for performance...
