Stored Procedures Instrumentation in MariaDB 10.5

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...