Overview of detailed slow query logging in MySQL 8: log_slow_extra

Every MySQL 8 minor release comes with a good number of bug fixes as well as exciting new features. MySQL 8.0.14 introduced the new log_slow_extra parameter. It is used to enable additional fields in the MySQL slow query log. They will help you get more information about the query and its statistics. In this blog post, I’ll cover the following topics explaining this feature in a better way:

• Configuration
• Slow query log format: OLD vs. NEW
• Explaining the new fields with examples

Note. Currently this feature is only available with FILE-based slow query logging (log_output=FILE). TABLE is unaffected.

At Vettabase, we have already created an article covering this topic, please refer to Logging all MariaDB and MySQL queries into the Slow Log.

Configuration

This feature is disabled by default. To use it, we have to enable the “log_slow_extra” parameter, which is a dynamic variable we can set without MySQL restart.

mysql> SELECT @@log_slow_extra;
+------------------+
| @@log_slow_extra |
+------------------+
|        0         |
+------------------+
mysql> SET PERSIST log_slow_extra = ON;
mysql> SELECT @@log_slow_extra;
+------------------+
| @@log_slow_extra |
+------------------+
|        1         |
+------------------+

Slow query log format – OLD vs NEW

Here’s the old format, with log_slow_extra=OFF:

# Time: 2023-02-20T21:55:27.304555Z
# User@Host: root[root] @ localhost []  Id:    20
# Query_time: 0.001276  Lock_time: 0.000006 Rows_sent: 10  Rows_examined: 50
SET timestamp=1676930127;
select distinct(k) from sbtest1 where id between 4728311 and 4728350 order by k desc limit 10;

Here’s the new format, with log_slow_extra=ON:

# Time: 2023-02-20T21:56:23.949255Z
# User@Host: root[root] @ localhost []  Id:    21
# Query_time: 0.001202  Lock_time: 0.000007 Rows_sent: 10  Rows_examined: 50 Thread_id: 21 Errno: 0 Killed: 0 Bytes_received: 100 Bytes_sent: 184 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 40 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 41 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 10 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 1 Start: 2023-02-20T21:56:23.948053Z End: 2023-02-20T21:56:23.949255Z
SET timestamp=1676930183;
select distinct(k) from sbtest1 where id between 4728311 and 4728350 order by k desc limit 10;

As we see in the comparison above, the new feature has around 20 additional fields, and they are providing more statistics about the query for analysis. Below you can find the complete list of new fields that were added in the MySQL 8.0.14 release.

• Thread_id
• Errno
• Killed
• Bytes_received
• Bytes_sent
• Read_first
• Read_last
• Read_key
• Read_next
• Read_prev
• Read_rnd
• Read_rnd_next
• Sort_merge_passes
• Sort_range_count
• Sort_rows
• Sort_scan_count
• Created_tmp_disk_tables
• Created_tmp_tables
• Start
• End

Explaining the new fields with examples

Finding the failed queries

With the extended slow query log, it is possible to find query execution status. The fields Errorno and Killed are dedicated to provide these details.

For example, I’m going to manually fail one statement and will check the status for that query in the slow query log.

SET SESSION max_execution_time = 1000;
Query OK, 0 rows affected (0.00 sec)

mysql> select count(*) from sbtest1;
ERROR 1317 (70100): Query execution was interrupted

From the above output, I manually failed a SELECT query by setting the lower execution time. Let’s check the slow query log for this query.

# Time: 2023-02-20T22:34:27.453691Z
# User@Host: root[root] @ localhost []  Id:    25
# Query_time: 1.014404  Lock_time: 0.000029 Rows_sent: 0  Rows_examined: 0 Thread_id: 25 Errno: 1317 Killed: 0 Bytes_received: 35 Bytes_sent: 83 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2023-02-20T22:34:26.439287Z End: 2023-02-20T22:34:27.453691Z
SET timestamp=1676932466;
select count(*) from sbtest1;

As I highlighted above, the field Errorno is updated with the error code. So, this is working as expected! In this way, we can find the query execution status from the slow query log itself.

Note. For some reason, the Killed: counter is not updated. I suspect this is a bug. Created the bug report for it as well. You can track it here.

Finding the sort operations

The new feature has the following fields to provide information about the sorting operations. This information is gathered from the status variables.

• Sort_merge_passes
• Sort_range_count
• Sort_rows
• Sort_scan_count

Let’s create some sorting operations in MySQL and find them in the slow query log. 

mysql> select distinct(k) from sbtest1 where id between 4728311 and 4728350 order by k desc limit 10;
0b51dfb8a69fe0f1821c06e2920103d1 -
10 rows in set (0.00 sec)

mysql> nopager; SHOW SESSION STATUS LIKE 'sort%';
PAGER set to stdout
+-------------------+-------+
| Variable_name     | Value |
+-------------------+-------+
| Sort_merge_passes   | 0   |
| Sort_range          | 0   |
| Sort_rows           | 10  |
| Sort_scan           | 1   |
+-------------------+-------+
4 rows in set (0.00 sec)

I have run the above SELECT with ORDER BY to create the sorting events. Above, I have shared the respective status parameters as well. Let’s check the MySQL slow query log.

# administrator command: Quit;
# Time: 2023-02-20T22:43:00.558687Z
# User@Host: root[root] @ localhost []  Id:    26
# Query_time: 0.002374  Lock_time: 0.000007 Rows_sent: 10  Rows_examined: 50 Thread_id: 26 Errno: 0 Killed: 0 Bytes_received: 100 Bytes_sent: 184 Read_first: 0 Read_last: 0 Read_key: 1 Read_next: 40 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 41 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 10 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 1 Start: 2023-02-20T22:43:00.556313Z End: 2023-02-20T22:43:00.558687Z
SET timestamp=1676932980;
select distinct(k) from sbtest1 where id between 4728311 and 4728350 order by k desc limit 10;

As I highlighted in the above output, we can make sure the Sort_rows and Sort_count are updated same as status parameters.

Finding the temporary tables information

The new feature has the following two fields, that will provide the information about the temporary tables. It provides the per query status for in-memory and on-disk temporary tables. The data is collected from the status variables.

• Created_tmp_disk_tables
• Created_tmp_tables

Let’s create the temporary tables manually and verify the status in a slow query log.

mysql> pager md5sum
PAGER set to 'md5sum'

mysql> select distinct(k) from sbtest1 order by k desc limit 100000;
a3b23ff9a0fa1cdff38b03da922f5592 -
100000 rows in set (2.39 sec)

mysql> nopager; show session status like 'Created_tmp%tables';
PAGER set to stdout
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Created_tmp_disk_tables | 1     |
| Created_tmp_tables      | 1     |
+-------------------------+-------+
2 rows in set (0.00 sec)

The query above has created one in-memory and one on-disk temporary tables. 

# administrator command: Quit;
# Time: 2023-02-20T22:56:15.930561Z
# User@Host: root[root] @ localhost []  Id:    28
# Query_time: 2.390461  Lock_time: 0.000007 Rows_sent: 100000  Rows_examined: 100000 Thread_id: 28 Errno: 0 Killed: 0 Bytes_received: 67 Bytes_sent: 1200064 Read_first: 2 Read_last: 1 Read_key: 869997 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 1051890 Sort_merge_passes: 11 Sort_range_count: 0 Sort_rows: 100000 Sort_scan_count: 1 Created_tmp_disk_tables: 1 Created_tmp_tables: 1 Start: 2023-02-20T22:56:13.540100Z End: 2023-02-20T22:56:15.930561Z
SET timestamp=1676933773;
select distinct(k) from sbtest1 order by k desc limit 100000;

As I highlighted, it has the same value, and the status appears in the slow query log.

Other useful information

• We can find the query’s start and end time in the slow query log.
• We can find the Query Handler status in the slow query log.

# administrator command: Quit;
# Time: 2023-02-20T22:56:15.930561Z
# User@Host: root[root] @ localhost []  Id:    28
# Query_time: 2.390461  Lock_time: 0.000007 Rows_sent: 100000  Rows_examined: 100000 Thread_id: 28 Errno: 0 Killed: 0 Bytes_received: 67 Bytes_sent: 1200064 Read_first: 2 Read_last: 1 Read_key: 869997 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 1051890 Sort_merge_passes: 11 Sort_range_count: 0 Sort_rows: 100000 Sort_scan_count: 1 Created_tmp_disk_tables: 1 Created_tmp_tables: 1 Start: 2023-02-20T22:56:13.540100Z End: 2023-02-20T22:56:15.930561Z
SET timestamp=1676933773;
select distinct(k) from sbtest1 order by k desc limit 100000;

Conclusion

As explained in this article, the extended slow query log support is a very useful feature as it provides good statistics for analysis. It may assume some additional disk space usage. As mentioned, currently it doesn’t support TABLE-based logging (mysql.slow_log). TABLE-based logging comes with more locking, so concurrency might be heavily affected.

Percona Server for MySQL and MariaDB servers have had extended slow query logging support for some years. They also have some additional fields to provide more insights. To enable this feature in these database management systems, you need to enable the log_slow_verbosity parameter.

Sri Sakthivel