Percona Server for MySQL Highlights – Extended Slow Query Logging

Last year, I made the first post in a small series, which aimed to highlight unique features of Percona Server for MySQL, by discussing binlog_space_limit option.

Today, I am going to discuss another important type of log available in MySQL that is enhanced in Percona Server for MySQL – the slow query log. The reason why I am doing this is that although this extension has existed since the very early times of versions 5.1 (over 10 years ago!), many people are still unaware of it, which I see from time to time when working with Support customers.

Default Slow Log Inadequacy

How many times have you been wondering why, whilst reviewing slow query logs, the very same query occasionally runs way slower than usual? There may be many reasons for that, but the standard slow query log does not always provide any helpful information about that. Let’s take a look at these two real test examples:

# Time: 2020-03-29T21:21:43.080863Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 18.234596 Lock_time: 0.000602 Rows_sent: 1 Rows_examined: 6317755 Rows_affected: 0
# Bytes_sent: 253
use employees;
SET timestamp=1585524084;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

vs

# Time: 2020-03-29T21:22:05.637495Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 2.681241 Lock_time: 0.000276 Rows_sent: 1 Rows_examined: 6317755 Rows_affected: 0
# Bytes_sent: 253
SET timestamp=1585524122;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

The most important information that usually gives a good clue on why it is slow – Rows_examined – is the same in both cases. So where dies the big difference in execution time come from?

Extended Slow Query Log Virtue

And here comes the extended verbosity mode for slow log available in Percona Server for MySQL. By simply using log_slow_verbosity=full variable, here is how similar log entries now look:

# Time: 2020-03-29T23:26:52.133388Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 18.272430 Lock_time: 0.000418 Rows_sent: 1 Rows_examined: 6317755 Rows_affected: 0
# Bytes_sent: 253 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 4915 InnoDB_IO_r_bytes: 80527360 InnoDB_IO_r_wait: 14.253396
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 6099
SET timestamp=1585524393;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

vs

# Time: 2020-03-29T23:27:01.031350Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 2.726639 Lock_time: 0.000268 Rows_sent: 1 Rows_examined: 6317755 Rows_affected: 0
# Bytes_sent: 253 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: 0
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 6098
SET timestamp=1585524418;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

So much more information! And we can now easily find the difference – InnoDB IO information. Basically the slow instance of the query had to read many data pages from disk, while the fast one clearly took advantage of the buffer pool.

That’s not all, we can be even more verbose and make the slow log print full query profiling info as well:

mysql > \! tail -11 /home/przemek/sandboxes/msb_ps8_0_18/data/przemek-dbg-slow.log|sed "s/ Profile/\nProfile/g"
Time Id Command Argument
# Time: 2020-03-30T00:23:38.017357Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Schema: employees Last_errno: 0 Killed: 0
# Query_time: 18.017249 Lock_time: 0.000537 Rows_sent: 1 Rows_examined: 6317755 Rows_affected: 0
# Bytes_sent: 253
#
Profile_starting: 0.000142
Profile_starting_cpu: 0.000142
Profile_Executing_hook_on_transaction_begin.: 0.000006
Profile_Executing_hook_on_transaction_begin._cpu: 0.000006
Profile_starting: 0.000011
Profile_starting_cpu: 0.000011
Profile_checking_permissions: 0.000006
Profile_checking_permissions_cpu: 0.000006
Profile_checking_permissions: 0.000003
Profile_checking_permissions_cpu: 0.000003
Profile_checking_permissions: 0.000003
Profile_checking_permissions_cpu: 0.000003
Profile_checking_permissions: 0.000003
Profile_checking_permissions_cpu: 0.000003
Profile_checking_permissions: 0.000108
Profile_checking_permissions_cpu: 0.000109
Profile_Opening_tables: 0.000247
Profile_Opening_tables_cpu: 0.000247
Profile_init: 0.000012
Profile_init_cpu: 0.000011
Profile_System_lock: 0.000015
Profile_System_lock_cpu: 0.000015
Profile_optimizing: 0.000022
Profile_optimizing_cpu: 0.000022
Profile_statistics: 0.000171
Profile_statistics_cpu: 0.000171
Profile_preparing: 0.000058
Profile_preparing_cpu: 0.000065
Profile_optimizing: 0.000017
Profile_optimizing_cpu: 0.000009
Profile_statistics: 0.000016
Profile_statistics_cpu: 0.000016
Profile_preparing: 0.000028
Profile_preparing_cpu: 0.000028
Profile_executing: 0.003004
Profile_executing_cpu: 0.000687
Profile_executing: 18.013309
Profile_executing_cpu: 4.507004
Profile_end: 0.000012
Profile_end_cpu: 0.000011
Profile_query_end: 0.000008
Profile_query_end_cpu: 0.000007
Profile_waiting_for_handler_commit: 0.000014
Profile_waiting_for_handler_commit_cpu: 0.000014
Profile_closing_tables: 0.000015
Profile_closing_tables_cpu: 0.000014
Profile_freeing_items: 0.000030
Profile_freeing_items_cpu: 0.000030
Profile_logging_slow_query: 0.000003
Profile_logging_slow_query_cpu: 0.000003
#
Profile_total: 18.017262
Profile_total_cpu: 4.508638
use employees;
SET timestamp=1585527800;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

And there are more perks in the extended slow query logging!

Safety For Busy Production Server and More

How many times were you concerned about using long_query_time=0 (or just the very low value of), because logging hundreds or thousands of queries per second on a busy system could be too much overhead? Two very useful options come handy here: log_slow_filter and log_slow_rate_limit. For example, you can order the server to log only queries that do joins without using indexes, but only 1% of such queries will be logged, with the following settings:

log_slow_filter = full_join
log_slow_rate_type = query
log_slow_rate_limit = 100

Of course, all those settings are dynamic and you can control whether they will apply to local sessions only or to all connections.
It is important to mention here, that other Percona tools, like pt-query-digest or Percona Monitoring and Management (PMM), can take advantage of the extra information. Here is an example of Query Analytics view in PMM using the extra InnoDB details in its statistics:

You will find more details about this rich, yet not very well known, feature set in our documentation pages.

MySQL 8.0 Extra

Since MySQL 8.0.14 Community Edition (and Percona Server for MySQL as well), also in the upstream, another variant of extended slow query log info was implemented, which however only partially overlaps with Percona features. Basically, you can now make the status handlers printed as well, by using log_slow_extra=1. An example entry for the same query looks like that:

# Time: 2020-03-30T09:31:48.485389Z
# User@Host: msandbox[msandbox] @ localhost [] Id: 8
# Query_time: 2.722842 Lock_time: 0.000315 Rows_sent: 1 Rows_examined: 6317755 Thread_id: 8 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 253 Read_first: 2 Read_last: 0 Read_key: 331615 Read_next: 3473707 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 2844048 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: 2020-03-30T09:31:45.762547Z End: 2020-03-30T09:31:48.485389Z Schema: employees Rows_affected: 0

SET timestamp=1585560705;
select hire_date,dept_name,salary from salaries join dept_emp using(emp_no) join departments using(dept_no) join employees using(emp_no) where salary=(select max(salary) from salaries);

This can be super useful in cases where we want to check if the execution plan was changing. Interestingly, you can enable both extensions at the same time if needed.

Slow Log Automatic Rotation

Tired of maintaining logrotate or custom scripts that keep your disk space safe from too bloated logs? There are new options in Percona Server for MySQL 5.7 that can make DBA/Sysadmin life easier – max_slowlog_size and max_slowlog_files. You may now set up limits after which the log will be automatically rotated and removed.

This auto-rotating functionality was not yet ported to Percona Server for MySQL 8.0 though. But if you think such should exist in MySQL, I’d suggest you vote for this 12-year-old feature request 🙂 https://bugs.mysql.com/bug.php?id=38702

Documentation reference:

Slow Query Log

Percona Server specific settings

by Przemysław Malkowski via Percona Database Performance Blog