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:
1 2 3 4 5 6 7 8 | # 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
1 2 3 4 5 6 7 | # 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:
1 2 3 4 5 6 7 8 9 10 11 12 13 | # 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
1 2 3 4 5 6 7 8 9 10 11 12 13 | # 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:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 | 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:
1 2 3 | 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:
1 2 3 4 5 6 | # 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:
Percona Server specific settings
Our solution brief “Get Up and Running with Percona Server for MySQL” outlines setting up a MySQL® database on-premises using Percona Server for MySQL. It includes failover and basic business continuity components.
