Wrong execution time counting in INFORMATION_SCHEMA.QUERY_RESPONSE_TIME for stored procedures

Bug #999309 reported by Vlad Lesin on 2012-05-14
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.1
Won't Fix
Medium
Unassigned
5.5
Triaged
Medium
Unassigned
5.6
Triaged
Medium
Unassigned
5.7
Triaged
Medium
Unassigned

Bug Description

It seems QUERY_RESPONSE_TIME feature counts total execution time wrong for stored procedures.

The first it counts statements execution time inside of stored procedure cumulatively. And it counts the total execution time of "call" statement twice - one for the statements inside stored procedure, second - for "CALL" itself. For example, if we have the following SP:

create procedure aaa()
begin
  select sleep(2);
  select sleep(2);
end

we expect the total 2(or 3?) queries with execution time between 1s and 10s and the total execution time of such queries is 4(or 8?) seconds.

But really we have 10 seconds which is counted as:

2 (the first sleep) + 4 (the first sleep + the second one) + 4 (the "call" itself) = 10.

We can check that behavior the following way:

mysql> call aaa();
+----------+
| sleep(2) |
+----------+
| 0 |
+----------+
1 row in set (2.03 sec)

+----------+
| sleep(2) |
+----------+
| 0 |
+----------+
1 row in set (4.32 sec)

Query OK, 0 rows affected (4.32 sec)

mysql> SELECT * from INFORMATION_SCHEMA.QUERY_RESPONSE_TIME;
+----------------+-------+----------------+
| time | count | total |
+----------------+-------+----------------+
| 0.000001 | 0 | 0.000000 |
| 0.000010 | 0 | 0.000000 |
| 0.000100 | 0 | 0.000000 |
| 0.001000 | 2 | 0.001044 |
| 0.010000 | 1 | 0.002569 |
| 0.100000 | 2 | 0.032284 |
| 1.000000 | 0 | 0.000000 |
| 10.000000 | 3 | 10.579363 | <<<<<<<<
| 100.000000 | 0 | 0.000000 |
| 1000.000000 | 0 | 0.000000 |
| 10000.000000 | 0 | 0.000000 |
| 100000.000000 | 0 | 0.000000 |
| 1000000.000000 | 0 | 0.000000 |
| TOO LONG | 0 | TOO LONG |
+----------------+-------+----------------+
14 rows in set (0.00 sec)

tags: added: query-response-time

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1249

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers