MySQL Bugs: #96537: Differing error for MAX_EXECUTION_TIME depending on query stage at termination

Bug #96537	Differing error for MAX_EXECUTION_TIME depending on query stage at termination
Submitted:	14 Aug 2019 17:14	Modified:	22 Oct 2019 22:11
Reporter:	Jeremy Cole (Basic Quality Contributor) (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S3 (Non-critical)
Version:	5.7, 5.7.27, 8.0.17	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	1028, 3024, error, max_execution_time

Description:
When a query is terminated due to exceeding its maximum execution time specified using the MAX_EXECUTION_TIME hint, the error produced will differ depending on the query stage at termination. Most queries will produce ER_QUERY_TIMEOUT (3024), but if a query is terminated during filesort, ER_FILSORT_ABORT (1028) will be produced instead.

This makes it unnecessarily harder to trap these errors and respond correctly. 

How to repeat:
Using a simple table with the sysbench structure:

CREATE TABLE `t` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT '0',
  `c` char(120) NOT NULL DEFAULT '',
  `pad` char(60) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB;

<insert 500 rows as appropriate>

> select count(*) from t;
+----------+
| count(*) |
+----------+
|      500 |
+----------+

A query that gets terminated before sort produces error 3024 as expected:

> select /*+ max_execution_time(50) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded

If the same query is terminated during filesort, error 1028 is produced instead of error 3024:

> select /*+ max_execution_time(300) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 1028 (HY000): Sort aborted: Query execution was interrupted, maximum statement execution time exceeded

Suggested fix:
When a query is terminated due to exceeding maximum execution time, capture the ER_FILSORT_ABORT (1028) error internally and translate it to ER_QUERY_TIMEOUT (3024).

Note this was noted originally in Rails: https://github.com/rails/rails/pull/36932

Hello Jeremy,

Thank you for the report and test case.
Observed this with 5.7.27 build.

regards,
Umesh

- 5.7.27

DROP TABLE if exists t;
CREATE TABLE `t` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT '0',
  `c` char(120) NOT NULL DEFAULT '',
  `pad` char(60) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB;

set @id:=0;
insert into `t` values(@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60));
insert into `t`(`id`,`k`,`c`,`pad`) select  @id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)  from `t` k1, `t` k2, `t` k3, `t` k4,`t` k5,`t` k6, `t` k7, `t` k8, `t` k9,`t` k0,`t` ka, `t` kb, `t` kc, `t` kd limit  500;  

-- 5.7.27

mysql>
mysql> insert into `t`(`id`,`k`,`c`,`pad`) select  @id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)  from `t` k1, `t` k2, `t` k3, `t` k4,`t` k5,`t` k6, `t` k7, `t` k8, `t` k9,`t` k0,`t` ka, `t` kb, `t` kc, `t` kd limit  500;
Query OK, 500 rows affected (0.07 sec)
Records: 500  Duplicates: 0  Warnings: 0

mysql> select /*+ max_execution_time(50) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded
mysql>
mysql> select /*+ max_execution_time(300) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 1028 (HY000): Sort aborted: Query execution was interrupted, maximum statement execution time exceeded
mysql>
mysql> show variables like '%version%';
+-------------------------+------------------------------+
| Variable_name           | Value                        |
+-------------------------+------------------------------+
| innodb_version          | 5.7.27                       |
| protocol_version        | 10                           |
| slave_type_conversions  |                              |
| tls_version             | TLSv1,TLSv1.1                |
| version                 | 5.7.27                       |
| version_comment         | MySQL Community Server (GPL) |
| version_compile_machine | x86_64                       |
| version_compile_os      | linux-glibc2.12              |
+-------------------------+------------------------------+
8 rows in set (0.00 sec)

 cat /etc/*release
Oracle Linux Server release 7.1
NAME="Oracle Linux Server"
VERSION="7.1"
ID="ol"
VERSION_ID="7.1"
PRETTY_NAME="Oracle Linux Server 7.1"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:oracle:linux:7:1"
HOME_URL="https://linux.oracle.com/"
BUG_REPORT_URL="https://bugzilla.oracle.com/"

ORACLE_BUGZILLA_PRODUCT="Oracle Linux 7"
ORACLE_BUGZILLA_PRODUCT_VERSION=7.1
ORACLE_SUPPORT_PRODUCT="Oracle Linux"
ORACLE_SUPPORT_PRODUCT_VERSION=7.1
Red Hat Enterprise Linux Server release 7.1 (Maipo)
Oracle Linux Server release 7.1

- 8.0.17

 bin/mysql -uroot -S /tmp/mysql_ushastry.sock
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 8.0.17 MySQL Community Server - GPL

Copyright (c) 2000, 2019, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> create database test;
Query OK, 1 row affected (0.00 sec)

mysql> use test
Database changed
mysql> DROP TABLE if exists t;
CREATE TABLE `t` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `k` int(11) NOT NULL DEFAULT '0',
  `c` char(120) NOT NULL DEFAULT '',
  `pad` char(60) NOT NULL DEFAULT '',
  PRIMARY KEY (`id`),
  KEY `k_1` (`k`)
) ENGINE=InnoDB;

set @id:=0;
insert into `t` values(@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60));
insert into `t`(`id`,`k`,`c`,`pad`) select  @id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)  from `t` k1, `t` k2, `t` k3, `t` k4,`t` k5,`t` k6, `t` k7, `t` k8, `t` k9,`t` k0,`t` ka, `t` kb, `t` kc, `t` kd limit  500;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> CREATE TABLE `t` (
    ->   `id` int(11) NOT NULL AUTO_INCREMENT,
    ->   `k` int(11) NOT NULL DEFAULT '0',
    ->   `c` char(120) NOT NULL DEFAULT '',
    ->   `pad` char(60) NOT NULL DEFAULT '',
    ->   PRIMARY KEY (`id`),
    ->   KEY `k_1` (`k`)
    -> ) ENGINE=InnoDB;
Query OK, 0 rows affected, 2 warnings (0.01 sec)

mysql>
mysql> set @id:=0;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into `t` values(@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)), (@id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60));
Query OK, 4 rows affected, 8 warnings (0.01 sec)
Records: 4  Duplicates: 0  Warnings: 8

mysql> insert into `t`(`id`,`k`,`c`,`pad`) select  @id:=@id+1,@id:=@id+1,repeat('A',120),repeat('A',60)  from `t` k1, `t` k2, `t` k3, `t` k4,`t` k5,`t` k6, `t` k7, `t` k8, `t` k9,`t` k0,`t` ka, `t` kb, `t` kc, `t` kd limit  500;
Query OK, 500 rows affected, 2 warnings (0.06 sec)
Records: 500  Duplicates: 0  Warnings: 2

mysql> show warnings;
+---------+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Level   | Code | Message                                                                                                                                                                                              |
+---------+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | Setting user variables within expressions is deprecated and will be removed in a future release. Consider alternatives: 'SET variable=expression, ...', or 'SELECT expression(s) INTO variables(s)'. |
| Warning | 1287 | Setting user variables within expressions is deprecated and will be removed in a future release. Consider alternatives: 'SET variable=expression, ...', or 'SELECT expression(s) INTO variables(s)'. |
+---------+------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
2 rows in set (0.00 sec)

mysql> select /*+ max_execution_time(50) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 3024 (HY000): Query execution was interrupted, maximum statement execution time exceeded
mysql>
mysql> select /*+ max_execution_time(300) */ * from t a, t b order by a.pad asc, b.pad desc limit 1;
ERROR 1028 (HY000): Sort aborted: Query execution was interrupted, maximum statement execution time exceeded

DOcumented fix in the MySQL 8.0.19 changelog as follows:

    When a query terminated due to exceeding the time specified
    using the MAX_EXECUTION_TIME hint, the error produced differed
    depending on the stage of the query. In particular, if the query
    terminated during a filesort, the error raised was
    ER_FILSORT_ABORT, even though in such cases the query should
    always exit with ER_QUERY_TIMEOUT. This made it unnecessarily
    difficult to trap such errors and to handle them correctly.

    This fix removes the error codes ER_FILSORT_ABORT and
    ER_FILESORT_TERMINATED.

Closed.