MariaDB: slow stored procedures, performance schema vs slow log

Percona Monitoring and Management (PMM) PMM 3.x
1

Heyo! I’ve been using PMM to find and resolve performance issues, and i’m running into a slight hurdle:

QAN shows that some stored procedures are quite slow. Now, i know its entirely possible to find out why its slow without something like PMM (SET profiling=1; CALL procedure…; SHOW profiles;) but i have to do that for every stored procedure, only to then find out that for some the effort to optimize them is too large to be worth it.

I think ideally, PMM would be able to “see inside” stored procedures somehow. Maybe thats already possible, but i want to ask to make sure that i’m not breaking things, as i could not find any documentation about this.

I’m currently using performance schema, as the docs recommend that for recent MariaDB versions.

MariaDB has a variable log_slow_disabled_statements which defaults to 'sp'. If i remove sp from it, the slow log will contain the individual queries run from within a stored procedure.

Now, my questions:

  1. Is there a config i’ve missed which either enables the PMM client to read the individual queries done by a procedure from performance schema, or makes MariaDB put those queries into performance schema in the first place?
    2.Does PMM/QAN understand the # Stored_routine: db.ProcedureName syntax which links the individual queries to the procedure?
  2. Does PMM/QAN properly calculate the time which is logged for the individual quries inside a stored procedure? It would have to subtract the difference between this and the previous query from within the same # Stored_routine: db.ProcedureName as the query time seems to be a rolling sum.
2

I think i partially answered myself. After writing this i thought “surely, it’d be simple enough to find out if the slow log stored procedures are supported by searching through the code” and looking at the slow log parser theres nothing that looks like it matches Stored_routine. In the whole repo theres basically no mention of Stored_routine or routine or Stored in a context that makes it seem like its handling the query times.

So it seems like slow log without the sp filter is not just unsupported, but will lead to tons of flawed data since each part of the stored procedure will count as sum(previous procedure statements) + self time instead of just self time. That means a simple SELECT 1+1; could show up as taking 1 hour to complete if its at the end of a 1 hour long procedure (as an extreme example).

3

There is no config for this. It is a flaw in MySQL that queries inside stored procedures are not logged to slow query log, or P_S.

I don’t believe so. PMM will see the query as any other query, and not tied to a specific stored procedure.

Edit: Removed MariaDB

4

There is no config for this. It is a flaw in MySQL/MariaDB that queries inside stored procedures are not logged to slow query log, or P_S.

This is wrong. At least for slow query log, you can enable logging of stored procedure queries by setting log_slow_disabled_statements='' - it defaults to log_slow_disabled_statements='sp', which filters out the stored procedure queries. Thats how i get the # Stored_routine lines in my slow query log. My question was if PMM has a config to enable it to understand this.

I suppose that this post is a feature request now. Should i write a proper feature request somewhere else (github, issue tracker)?

5

My mistake on MariaDB. Community MySQL doesn’t have this feature, but Percona MySQL has had it for many years.

I see the line # Stored_routine: world.CountCityByName in Percona MySQL as well when using log_slow_sp_statements=on

What exactly are you expecting PMM to do with this information? Do you want to be able to search/filter?

6

What exactly are you expecting PMM to do with this information? Do you want to be able to search/filter?

I explained in my post: The way it logs things, query time is accumulated for every query belonging to the same stored procedure call.

That means if my stored procedure first does an expensove query that take 100s, and then SELECT 1 + 1; the log for that addition will have a Query time of 100s + some insignificant amount - while the expensive query before it also had a Query time of 100s. That means PMM, right now, would falsely think that SELECT 1 + 1 takes 100+ seconds.

So what i want PMM to do: Subtract the Query time of each part of a stored procedure from the previous part of the same stored procedure, to get the actual query time.

7 
mysql [localhost:8043] {msandbox} (world) > DELIMITER $$
mysql [localhost:8043] {msandbox} (world) > CREATE PROCEDURE `CountCityByName`(IN p_name VARCHAR(255))
    -> BEGIN
    -> SELECT SLEEP(10); SELECT COUNT(*) FROM world.city WHERE Name = p_name;
    -> END$$
Query OK, 0 rows affected (0.00 sec)

mysql [localhost:8043] {msandbox} (world) > DELIMITER ;

mysql [localhost:8043] {msandbox} (world) > CALL CountCityByName('Houston');
+-----------+
| SLEEP(10) |
+-----------+
|         0 |
+-----------+
1 row in set (10.00 sec)

+----------+
| COUNT(*) |
+----------+
|        1 |
+----------+
1 row in set (10.01 sec)


# Time: 2026-01-13T22:21:18.909235Z
# User@Host: msandbox[msandbox] @ localhost []  Id:  1556
# Schema: world  Last_errno: 0  Killed: 0
# Query_time: 10.000176  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 1  Rows_affected: 0  Bytes_sent: 57
# Stored_routine: world.CountCityByName
SET timestamp=1768342868;
SELECT SLEEP(10);
# Time: 2026-01-13T22:21:18.912575Z
# User@Host: msandbox[msandbox] @ localhost []  Id:  1556
# Schema: world  Last_errno: 0  Killed: 0
# Query_time: 0.003261  Lock_time: 0.000007  Rows_sent: 2  Rows_examined: 4080  Rows_affected: 0  Bytes_sent: 113
# Stored_routine: world.CountCityByName
SET timestamp=1768342878;
SELECT COUNT(*) FROM world.city WHERE Name =  NAME_CONST('p_name',_utf8mb4'Houston' COLLATE 'utf8mb4_0900_ai_ci');

What you describe does not appear to be the case here. The final select shows a query time of 0.003261. Your statement would imply that this should say 10.003261.