QueryException not thrown for MySQL max_execution_time

ethanttbui commented 3 years ago

Lumen Version: 6.0
PHP Version: 7.3 / 7.4
Database Driver & Version: MySQL 5.7.32

Description:

When using MySQL's max_execution_time in Lumen, an exception is not thrown on timeout. I tested this in pure PHP (7.3, 7.4 and 8.0), the behavior is correct. So, I believe the problem comes from how Lumen handles the exception returned by PDO.

Code

DB::statement("SET SESSION MAX_EXECUTION_TIME=1");
// some long running query
var_dump(DB::connection()->getPdo()->errorInfo())

Expected

array(3) {
  [0]=>
  string(5) "HY000"
  [1]=>
  int(3024)
  [2]=>
  string(74) "Query execution was interrupted, maximum statement execution time exceeded"
}

Actual

array(3) {
  [0]=>
  string(5) "00000"
  [1]=>
  NULL
  [2]=>
  NULL
}

Steps To Reproduce:

As described above

GrahamCampbell commented 3 years ago

Lumen 6 is not supported.

driesvints commented 3 years ago

Hey there,

Unfortunately we don't support this version anymore. Please check out our support policy on which versions we are currently supporting. Can you please try to upgrade to the latest version and see if your problem persists? If so, please open up a new issue and we'll help you out.

Thanks!

ethanttbui commented 3 years ago

Thank you all for replying. For those who are interested, the problem actually comes from both PDO and MySQL. MySQL returns different errors when the query is interrupted at different stages. When The query is interrupted at the Sending data stage, PDO will not detect an error and consider the query successful.

However, PDO works fine if we disable prepared statements (or enable, sorry that I can't remember clearly)

$pdo->setAttribute(PDO::ATTR_EMULATE_PREPARES, true);

In my case, I simply try-catch on the response as a workaround. When there's an uncatched error, the response will be empty. But you need to make sure that your query never returns an empty response otherwise, so it does not work for all cases.

piotrekkr commented 1 year ago

So stumbled upon this problem myself few days ago and made some tests using MySQL 8.0 and PHP 8.2.

I prepared a script to test this behaviour:

<?php

$dbh = new PDO(
    'mysql:host=127.0.0.1;port=3004;dbname=database;charset=utf8mb4',
    'user',
    'pass',
    [
        PDO::ATTR_ERRMODE => PDO::ERRMODE_EXCEPTION,
        PDO::ATTR_DEFAULT_FETCH_MODE => PDO::FETCH_ASSOC,
    ]
);

$queries = [
    "slow query >30s" => "
        SELECT COUNT(`s0_`.`id`) AS `sclr_0`
        FROM `step_archive` `s0_`
        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)
        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)
        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_id`)
        LEFT JOIN `shipping_request_pickup` `s4_` ON (`s4_`.`shipping_request_id` = `s3_`.`id`)
        WHERE
            `s0_`.`is_valid` = 1
            AND `u1_`.`order_id` IS NULL
            AND `s0_`.`modified` > NOW() - INTERVAL 1 YEAR
            AND (
                `u1_`.`id` = 0
                OR
                (
                    `s0_`.`customer_reference` LIKE '%REF%'
                    OR `s0_`.`delivery_city` LIKE '%REF%'
                    OR `s0_`.`delivery_country` LIKE '%REF%'
                    OR `s4_`.`pickup_city` LIKE '%REF%'
                    OR `s0_`.`name` LIKE '%REF%'
                )
            )
    ",
    "slow query >30s with short sleep" => "
        SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)
        FROM `step_archive` `s0_`
        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)
        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)
        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_id`)
        LEFT JOIN `shipping_request_pickup` `s4_` ON (`s4_`.`shipping_request_id` = `s3_`.`id`)
        WHERE
            `s0_`.`is_valid` = 1
            AND `u1_`.`order_id` IS NULL
            AND `s0_`.`modified` > NOW() - INTERVAL 1 YEAR
            AND (
                `u1_`.`id` = 0
                OR
                (
                    `s0_`.`customer_reference` LIKE '%REF%'
                    OR `s0_`.`delivery_city` LIKE '%REF%'
                    OR `s0_`.`delivery_country` LIKE '%REF%'
                    OR `s4_`.`pickup_city` LIKE '%REF%'
                    OR `s0_`.`name` LIKE '%REF%'
                )
            )
    ",
    "fast query (around 1s) with short sleep below limit" => "
        SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)
        FROM `step_archive` `s0_`
        WHERE
            `s0_`.`is_valid` = 1
            AND `s0_`.`modified` > NOW() - INTERVAL 6 MONTH
            AND (
              `s0_`.`customer_reference` LIKE 'REF%'
              OR `s0_`.`delivery_city` LIKE 'REF%'
              OR `s0_`.`delivery_country` LIKE 'REF%'
              OR `s0_`.`name` LIKE 'REF%'
            )
    ",
    "fast query with sleep above limit and with FROM" => "SELECT COUNT(id), SLEEP(10) FROM user",
    "fast query with sleep below limit and with FROM" => "SELECT COUNT(id), SLEEP(3) FROM user",
    "query with just sleep above limit" => "SELECT SLEEP(10)",
    "query with just sleep below limit" => "SELECT SLEEP(3)",
];

$dbh->exec('SET SESSION MAX_EXECUTION_TIME=5000, PROFILING=1');
$results = [];
foreach ($queries as $k => $q) {
    $result = [
        'start' => new DateTime(),
        'stop' => null,
        'query' => $q,
        'duration' => null,
        'result' => null,
        'error_info' => null,
        'exception' => null,
    ];
    try {
        $stmt = $dbh->query($q);
        $result['result'] = $stmt->fetchAll();
    } catch (\Throwable $e) {
        $result['exception'] = $e->getMessage();
    }
    $result['error_info'] = $dbh->errorInfo();
    $result['stop'] = new DateTime();
    $result['duration'] = $result['stop']->diff($result['start'])->format('%s.%f s');
    unset($result['start'], $result['stop']);
    $results[$k] = $result;
}
echo json_encode($results, JSON_PRETTY_PRINT), PHP_EOL;
echo "======= MYSQL STATS =========", PHP_EOL;
echo json_encode($dbh->query("SHOW PROFILES")->fetchAll(), JSON_PRETTY_PRINT), PHP_EOL;

Results are as follow:

{
    "slow query >30s": {
        "query": "\n        SELECT COUNT(`s0_`.`id`) AS `sclr_0`\n        FROM `step_archive` `s0_`\n        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)\n        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)\n        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_id`)\n        LEFT JOIN `shipping_request_pickup` `s4_` ON (`s4_`.`shipping_request_id` = `s3_`.`id`)\n        WHERE\n            `s0_`.`is_valid` = 1\n            AND `u1_`.`order_id` IS NULL\n            AND `s0_`.`modified` > NOW() - INTERVAL 1 YEAR\n            AND (\n                `u1_`.`id` = 0\n                OR\n                (\n                    `s0_`.`customer_reference` LIKE '%REF%'\n                    OR `s0_`.`delivery_city` LIKE '%REF%'\n                    OR `s0_`.`delivery_country` LIKE '%REF%'\n                    OR `s4_`.`pickup_city` LIKE '%REF%'\n                    OR `s0_`.`name` LIKE '%REF%'\n                )\n            )\n    ",
        "duration": "5.36920 s",
        "result": null,
        "error_info": [
            "HY000",
            3024,
            "Query execution was interrupted, maximum statement execution time exceeded"
        ],
        "exception": "SQLSTATE[HY000]: General error: 3024 Query execution was interrupted, maximum statement execution time exceeded"
    },
    "slow query >30s with short sleep": {
        "query": "\n        SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)\n        FROM `step_archive` `s0_`\n        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)\n        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)\n        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_id`)\n        LEFT JOIN `shipping_request_pickup` `s4_` ON (`s4_`.`shipping_request_id` = `s3_`.`id`)\n        WHERE\n            `s0_`.`is_valid` = 1\n            AND `u1_`.`order_id` IS NULL\n            AND `s0_`.`modified` > NOW() - INTERVAL 1 YEAR\n            AND (\n                `u1_`.`id` = 0\n                OR\n                (\n                    `s0_`.`customer_reference` LIKE '%REF%'\n                    OR `s0_`.`delivery_city` LIKE '%REF%'\n                    OR `s0_`.`delivery_country` LIKE '%REF%'\n                    OR `s4_`.`pickup_city` LIKE '%REF%'\n                    OR `s0_`.`name` LIKE '%REF%'\n                )\n            )\n    ",
        "duration": "5.37127 s",
        "result": null,
        "error_info": [
            "HY000",
            3024,
            "Query execution was interrupted, maximum statement execution time exceeded"
        ],
        "exception": "SQLSTATE[HY000]: General error: 3024 Query execution was interrupted, maximum statement execution time exceeded"
    },
    "fast query (around 1s) with short sleep below limit": {
        "query": "\n        SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)\n        FROM `step_archive` `s0_`\n        WHERE\n            `s0_`.`is_valid` = 1\n            AND `s0_`.`modified` > NOW() - INTERVAL 6 MONTH\n            AND (\n              `s0_`.`customer_reference` LIKE 'REF%'\n              OR `s0_`.`delivery_city` LIKE 'REF%'\n              OR `s0_`.`delivery_country` LIKE 'REF%'\n              OR `s0_`.`name` LIKE 'REF%'\n            )\n    ",
        "duration": "1.578609 s",
        "result": [
            {
                "sclr_0": 16,
                "SLEEP(1)": 0
            }
        ],
        "error_info": [
            "00000",
            null,
            null
        ],
        "exception": null
    },
    "fast query with sleep above limit and with FROM": {
        "query": "SELECT COUNT(id), SLEEP(10) FROM user",
        "duration": "5.39661 s",
        "result": [
            {
                "COUNT(id)": 27419,
                "SLEEP(10)": 1
            }
        ],
        "error_info": [
            "00000",
            null,
            null
        ],
        "exception": null
    },
    "fast query with sleep below limit and with FROM": {
        "query": "SELECT COUNT(id), SLEEP(3) FROM user",
        "duration": "3.42646 s",
        "result": [
            {
                "COUNT(id)": 27419,
                "SLEEP(3)": 0
            }
        ],
        "error_info": [
            "00000",
            null,
            null
        ],
        "exception": null
    },
    "query with just sleep above limit": {
        "query": "SELECT SLEEP(10)",
        "duration": "5.34809 s",
        "result": [
            {
                "SLEEP(10)": 1
            }
        ],
        "error_info": [
            "00000",
            null,
            null
        ],
        "exception": null
    },
    "query with just sleep below limit": {
        "query": "SELECT SLEEP(3)",
        "duration": "3.51699 s",
        "result": [
            {
                "SLEEP(3)": 0
            }
        ],
        "error_info": [
            "00000",
            null,
            null
        ],
        "exception": null
    }
}
======= MYSQL STATS =========
[
    {
        "Query_ID": 1,
        "Duration": 5.001551,
        "Query": "SELECT COUNT(`s0_`.`id`) AS `sclr_0`\n        FROM `step_archive` `s0_`\n        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)\n        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)\n        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_id`)\n      "
    },
    {
        "Query_ID": 2,
        "Duration": 5.0020715,
        "Query": "SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)\n        FROM `step_archive` `s0_`\n        LEFT JOIN `u_i_d` `u1_` ON (`u1_`.`quote_id` = `s0_`.`id`)\n        LEFT JOIN `quote` `q2_` ON (`q2_`.`id` = `s0_`.`quote_id`)\n        LEFT JOIN `shipping_request` `s3_` ON (`s3_`.`id` = `s0_`.`shipping_request_i"
    },
    {
        "Query_ID": 3,
        "Duration": 1.532444,
        "Query": "SELECT COUNT(`s0_`.`id`) AS `sclr_0`, SLEEP(1)\n        FROM `step_archive` `s0_`\n        WHERE\n            `s0_`.`is_valid` = 1\n            AND `s0_`.`modified` > NOW() - INTERVAL 6 MONTH\n            AND (\n              `s0_`.`customer_reference` LIKE 'REF%'\n              OR `s0_`.`delivery_city` LI"
    },
    {
        "Query_ID": 4,
        "Duration": 5.00115075,
        "Query": "SELECT COUNT(id), SLEEP(10) FROM user"
    },
    {
        "Query_ID": 5,
        "Duration": 3.00543575,
        "Query": "SELECT COUNT(id), SLEEP(3) FROM user"
    },
    {
        "Query_ID": 6,
        "Duration": 5.00128025,
        "Query": "SELECT SLEEP(10)"
    },
    {
        "Query_ID": 7,
        "Duration": 3.0005515,
        "Query": "SELECT SLEEP(3)"
    }
]

My observations are:

queries with just sleep() like select sleep(X):
- will never generate error
- will return 0 if below limit and 1 if above limit
if we query data and use sleep() at same time and:
- query (without sleep) is faster than limit then we will get results and no error (even if technically we exceeded limit because of sleep())
- query (without sleep) is slower than limit then we will get error and no results at all

Not sure if this is intended behavior. Maybe it is an issue with MySQL and not PHP.

laravel / lumen-framework

QueryException not thrown for MySQL max_execution_time #1188

Description:

Steps To Reproduce: