RDS: Long_query_time logging works curious

In MySQLWorkBench,

Duration time - is the time that query needs to be executed. You should try to minimize it when optimizing performance of sql query.

Fetch time - measures how long transferring fetched results take, which has nothing to do with query execution. I would not consider it as sql query debugging/optimization option since fetch time depends on network connection, which itself does not have anything to do with query optimization. If fetch time is bottleneck then more likely there's some networking problem.

Note: fetch time may vary on each query execution because sometimes results are cached, so they can be sent out quicker.

Please refer below forum for more information on Duration and Fetch times in MySQLWorkBench. We do have several third party articles explaining the same.

[+] https://forums.mysql.com/read.php?152,560430,560430#msg-560430

When it comes to MySQL Slow Query log,

[+] https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html

Query_time: duration The statement execution time in seconds.

Lock_time: duration The time to acquire locks in seconds.

I have performed simple testing with below setting from MySQL Client and MySQL Workbench, however I do not observe any differences in terms of execution time in SlowQuery logs in console and SlowQuery logs in CloudWatch.

Version: 8.0.mysql_aurora.3.02.0
slow_query_log = 1
log_output = FILE
long_query_time = 0.3

From MySQL Terminal:

mysql> select sleep(10); +-----------+ | sleep(10) | +-----------+ | 0 | +-----------+ 1 row in set (10.00 sec)

mysql> select sleep(1); +----------+ | sleep(1) | +----------+ | 0 | +----------+ 1 row in set (1.01 sec)

mysql> select sleep(0.5); +------------+ | sleep(0.5) | +------------+ | 0 | +------------+ 1 row in set (0.50 sec)

mysql> select sleep(0.2); +------------+ | sleep(0.2) | +------------+ | 0 | +------------+ 1 row in set (0.20 sec)

mysql> select sleep(0.8); +------------+ | sleep(0.8) | +------------+ | 0 | +------------+ 1 row in set (0.80 sec)

MySQL SlowQuery Log in Console:

Time Id Command Argument
Time: 2022-10-06T05:16:48.858424Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 14
Query_time: 10.000159 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665033398;
select sleep(10);
Time: 2022-10-06T05:17:12.159499Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 14
Query_time: 1.000166 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033431;
select sleep(1);
Time: 2022-10-06T05:17:34.905054Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 14
Query_time: 0.500164 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033454;
select sleep(0.5);
Time: 2022-10-06T05:19:21.209179Z
User@Host: admin[admin] @ [172.x1.xx.x] Id: 14
Query_time: 0.800173 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033560;
select sleep(0.8);
----------------------- END OF LOG ———————————

CloudWatch logs:

Time: 2022-10-06T05:16:48.858424Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 14
Query_time: 10.000159 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665033398;
select sleep(10);
Time: 2022-10-06T05:17:12.159499Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 14
Query_time: 1.000166 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033431;
select sleep(1);
Time: 2022-10-06T05:17:34.905054Z
User@Host: admin[admin] @ [172.x1.xx.x] Id: 14
Query_time: 0.500164 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033454;
select sleep(0.5);
Time: 2022-10-06T05:19:21.209179Z
User@Host: admin[admin] @ [172.x1.xx.x] Id: 14
Query_time: 0.800173 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665033560;
select sleep(0.8);

From MySQLWorkBench:

06:27:18 select sleep(10) LIMIT 0, 1000 1 row(s) returned 10.000 sec / 0.000 sec

06:28:19 select sleep(1) LIMIT 0, 1000 1 row(s) returned 1.000 sec / 0.000 sec

06:29:49 select sleep(0.5) LIMIT 0, 1000 1 row(s) returned 0.500 sec / 0.000 sec

06:30:08 select sleep(0.2) LIMIT 0, 1000 1 row(s) returned 0.203 sec / 0.000 sec

06:30:34 select sleep(0.8) LIMIT 0, 1000 1 row(s) returned 0.797 sec / 0.000 sec

MySQL SlowQuery Log in Console:

Time Id Command Argument
Time: 2022-10-06T06:27:28.822387Z
User@Host: admin[admin] @ [172.x1.xx.xxx] Id: 30
Query_time: 10.000138 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665037638;
select sleep(10)
LIMIT 0, 1000;
Time: 2022-10-06T06:28:20.709416Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 1.000203 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665037699;
select sleep(1)
LIMIT 0, 1000;
Time: 2022-10-06T06:29:50.340710Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 0.500165 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665037789;
select sleep(0.5)
LIMIT 0, 1000;
/rdsdbbin/oscar/bin/mysqld, Version: 8.0.23 (Source distribution). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
Time: 2022-10-06T06:30:35.104460Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 0.800165 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665037834;
select sleep(0.8)
LIMIT 0, 1000;
----------------------- END OF LOG ----------------------

CloudWatch logs:

Time: 2022-10-06T06:27:28.822387Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 10.000138 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665037638;
select sleep(10)
LIMIT 0, 1000;
Time: 2022-10-06T06:28:20.709416Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 1.000203 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665037699;
select sleep(1)
LIMIT 0, 1000;
Time: 2022-10-06T06:29:50.340710Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 0.500165 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
SET timestamp=1665037789;
select sleep(0.5)
LIMIT 0, 1000;
Time: 2022-10-06T06:30:35.104460Z
User@Host: admin[admin] @ [172.x1.xx.xx] Id: 30
Query_time: 0.800165 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 1
use test;
SET timestamp=1665037834;
select sleep(0.8)
LIMIT 0, 1000;