MAX_STATEMENT_TIME has no effect in a procedure after an interrupted sleep

[Elena Stepanova]

In the procedure below, SELECT SLEEP(..) is interrupted as expected; but SELECT COUNT(*) takes clearly longer that 1 millisecond, however it is not interrupted.

#----------------------------------

MySQL [test]> create table t1 (i int) engine=InnoDB;
Query OK, 0 rows affected (1.12 sec)

MySQL [test]> insert into t1 values (1),(2),(3),(4);
Query OK, 4 rows affected (0.56 sec)
Records: 4 Duplicates: 0 Warnings: 0

MySQL [test]> insert into t1 select a.* from t1 a, t1 b, t1 c, t1 d, t1 e, t1 f, t1 g;
Query OK, 16384 rows affected (4.47 sec)
Records: 16384 Duplicates: 0 Warnings: 0

MySQL [test]>
MySQL [test]> delimiter |
MySQL [test]> create procedure pr()
    -> begin
    -> select sleep(0.5);
    -> select sql_no_cache count(*) from t1;
    -> select sql_no_cache count(*) from t1;
    -> end |
Query OK, 0 rows affected (0.00 sec)

MySQL [test]> delimiter ;
MySQL [test]>
MySQL [test]> set max_statement_time = 1;
Query OK, 0 rows affected (0.00 sec)

MySQL [test]> call pr();
+------------+
| sleep(0.5) |
+------------+
| 1 |
+------------+
1 row in set (0.00 sec)

+----------+
| count(*) |
+----------+
| 16388 |
+----------+
1 row in set (0.29 sec)

+----------+
| count(*) |
+----------+
| 16388 |
+----------+
1 row in set (0.58 sec)

Query OK, 0 rows affected (0.58 sec)

#----------------------------------

Compare with this:

#----------------------------------

MySQL [test]> delimiter |
MySQL [test]> create procedure pr2()
    -> begin
    -> select 1;
    -> select sql_no_cache count(*) from t1;
    -> select sql_no_cache count(*) from t1;
    -> end |
Query OK, 0 rows affected (0.00 sec)

MySQL [test]> delimiter ;
MySQL [test]>
MySQL [test]> set max_statement_time = 1;
Query OK, 0 rows affected (0.00 sec)

MySQL [test]> call pr2();
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

ERROR 1885 (70101): Query execution was interrupted, max_statement_time exceeded

[Nilnandan Joshi (nilnandan-joshi)]

Able to reproduce the same with 5.6.21

mysql> create table t1 (i int) engine=InnoDB;
Query OK, 0 rows affected (0.04 sec)

mysql> insert into t1 values (1),(2),(3),(4);
Query OK, 4 rows affected (0.01 sec)
Records: 4 Duplicates: 0 Warnings: 0

mysql> insert into t1 select a.* from t1 a, t1 b, t1 c, t1 d, t1 e, t1 f, t1 g;
Query OK, 16384 rows affected (0.35 sec)
Records: 16384 Duplicates: 0 Warnings: 0

mysql> delimiter |
mysql> create procedure pr()
    -> begin
    -> select sleep(0.5);
    -> select sql_no_cache count(*) from t1;
    -> select sql_no_cache count(*) from t1;
    -> end |
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;
mysql>
mysql> set max_statement_time = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> call pr();
+------------+
| sleep(0.5) |
+------------+
| 1 |
+------------+
1 row in set (0.00 sec)

+----------+
| count(*) |
+----------+
| 16388 |
+----------+
1 row in set (0.01 sec)

+----------+
| count(*) |
+----------+
| 16388 |
+----------+
1 row in set (0.02 sec)

Query OK, 0 rows affected (0.02 sec)

mysql>
mysql>
mysql>
mysql>
mysql>
mysql> delimiter |
mysql>
mysql> create procedure pr2()
    -> begin
    -> select 1;
    -> select sql_no_cache count(*) from t1;
    -> select sql_no_cache count(*) from t1;
    -> end |
Query OK, 0 rows affected (0.00 sec)

mysql> delimiter ;
mysql>
mysql> set max_statement_time = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> call pr2();
+---+
| 1 |
+---+
| 1 |
+---+
1 row in set (0.00 sec)

ERROR 1885 (70101): Query execution was interrupted, max_statement_time exceeded
mysql>
mysql> select @@max_statement_time ;
+----------------------+
| @@max_statement_time |
+----------------------+
| 1 |
+----------------------+
1 row in set (0.00 sec)

mysql>

[Shahriyar Rzayev (rzayev-sehriyar)]

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