[#MDEV-29326] Slow log reporting wrong time for statements in stored procedure

When a statement in a stored procedure is slow to end up in the slow_query_log, and assuming that log_slow_disabled_statements is not set to blank, then a slow statement in a procedure is reported as the time it has taken since the procedure was started, not the statement itself. For example:

CREATE OR REPLACE PROCEDURE dosleep()

BEGIN

   DECLARE dummy1 VARCHAR(1);

   DECLARE dummy2 VARCHAR(1);

   SELECT sleep(1), '1' INTO dummy1, dummy2;

   SELECT sleep(1), '2' INTO dummy1, dummy2;

END;

# Time: 220818 16:04:33

# User@Host: root[root] @ localhost []

# Thread_id: 5  Schema: bmoper  QC_hit: No

# Query_time: 1.000926  Lock_time: 0.000105  Rows_sent: 0  Rows_examined: 0

# Rows_affected: 1  Bytes_sent: 0

# Stored_routine: bmoper.dosleep

SET timestamp=1660831473;

SELECT sleep(1), '1' INTO dummy1, dummy2;

# Time: 220818 16:04:35

# User@Host: root[root] @ localhost []

# Thread_id: 5  Schema: bmoper  QC_hit: No

# Query_time: 2.001449  Lock_time: 0.000105  Rows_sent: 0  Rows_examined: 0

# Rows_affected: 1  Bytes_sent: 0

# Stored_routine: bmoper.dosleep

SET timestamp=1660831475;

SELECT sleep(1), '2' INTO dummy1, dummy2;

# User@Host: root[root] @ localhost []

# Thread_id: 5  Schema: bmoper  QC_hit: No

# Query_time: 2.001570  Lock_time: 0.000105  Rows_sent: 0  Rows_examined: 0

# Rows_affected: 2  Bytes_sent: 11

SET timestamp=1660831475;

call dosleep();

If you look at the second of the statements in the slow log, it is reported to have a query time of 2.001449 seconds, which is clearly wrong. This gets particularily troublesome if some statements in the procedure does not end up in the slow query log, then it is impossible to determine how much time a statement has taken.

[MDEV-29326] Slow log reporting wrong time for statements in stored procedure Created: 2022-08-18 Updated: 2022-08-18
Status:	Open
Project:	MariaDB Server
Component/s:	Stored routines
Affects Version/s:	10.6.8
Fix Version/s:	None

[MDEV-29326] Slow log reporting wrong time for statements in stored procedure Created: 2022-08-18 Updated: 2022-08-18