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)
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)