Bug #68914 stored procedure execution runtime increase while repetitive calls
Submitted: 10 Apr 2013 8:34 Modified: 13 May 2013 20:30
Reporter: Dirk LANGE Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version:5.6.10 OS:Windows
Assigned to: CPU Architecture:Any

[10 Apr 2013 8:34] Dirk LANGE
Description:
under certain circumstances, repetitive calls of a stored procedure, e.g. in a rapid succession, show unexpected increase of individual effective execution runtime;
a single call event appears not to make a visible effect for an application, but a batch of 1000 makes it very obvious;

my sandbox:

* Server: Solaris 10 on x64_64, mysql-5.6.10-solaris10-x86_64
* Client: WinXP, mysql-5.6.10-win32

features:

* observed runtime increase factor from 15 to 20
* spotted the effect when doing a SELECT, but might happen independent on the procedure body
* the effect has trigger points, trigger seem to be some kind of periodic with respect to select_expression string
* generally so far a trigger point is defined by a certain length of the select_expression string portion and the number of the select_expressions
* below/above a critical trigger point string length the effect will appear/disappear
* the effect is independent on parametric/non-parametric type of a stored procedure
* the effect is independent on whether the stored procedure uses direct or prepared statement
* in comparison, the equivalent batch of statements called directly instead of wrapping in a stored procedure runs as quickly as expected
* it appears to be client lib dependent, it has happened with Linux CLI of older 5.1 versions, too, but later 5.1 and current 5.6 don't show the effect any more
(* FUNCTIONs have not been tested, but might be affected, too)
(* initially have been seeing the effect using ODBC, so there may be a link, too)

expected:

respectively short runtime for equivalent queries independent on select_expression string length

How to repeat:
- simplified pattern example
- compare tests 1..40 and 1..41 regarding call _test() "... rows affected  (0.xx sec)"
- another (reverting) trigger point in my test bed is between 1..81 and 1..82 (not shown here)
- there might be different trigger point string length in different test beds compared to what observed here
- replacing "1,2,3,..." by multiple function calls, e.g. "rand(),rand(),...", shows same effect

mysql> -- before first trigger point: 1..40

mysql> DROP PROCEDURE IF EXISTS _test;
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter //
mysql> CREATE PROCEDURE _test()
    -> SQL SECURITY DEFINER
    -> BEGIN
    -> select
    ->  1,2,3,4,5,6,7,8,9,10
    -> ,11,12,13,14,15,16,17,18,19,20
    -> ,21,22,23,24,25,26,27,28,29,30
    -> ,31,32,33,34,35,36,37,38,39,40
    -> ;
    -> END//
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;

mysql> call _test(); call _test(); call _test(); call _test();
+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.19 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
1 row in set (0.01 sec)

Query OK, 0 rows affected (0.31 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.20 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.30 sec)

mysql> -- after first trigger point: 1..41

mysql> DROP PROCEDURE IF EXISTS _test;
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter //
mysql> CREATE PROCEDURE _test()
    -> SQL SECURITY DEFINER
    -> BEGIN
    -> select
    ->  1,2,3,4,5,6,7,8,9,10
    -> ,11,12,13,14,15,16,17,18,19,20
    -> ,21,22,23,24,25,26,27,28,29,30
    -> ,31,32,33,34,35,36,37,38,39,40
    -> ,41
    -> ;
    -> END//
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;

mysql> call _test(); call _test(); call _test(); call _test();
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.01 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.00 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.02 sec)

+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
| 1 | 2 | 3 | 4 | 5 | 6 | 7 | ... | 37 | 38 | 39 | 40 | 41 |
+---+---+---+---+---+---+---+ ... +----+----+----+----+----+
1 row in set (0.00 sec)

Query OK, 0 rows affected (0.01 sec)
[13 Apr 2013 20:30] MySQL Verification Team
Thank you for the bug report. I assume your test is against a remote server. If yes please teast against a local host server so network issues can't mask the actual results. Thanks.
[14 May 2013 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".