Details
-
Bug
-
Status: Open (View Workflow)
-
Critical
-
Resolution: Unresolved
-
10.6.8
-
None
-
None
-
Linux
Description
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; |
If we then call this procedure and look in the slow log we see:
# 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.