Percona Server for MySQL 在慢查询日志方面的加强

Percona Server for MySQL 是 MySQL的一个重要的发行版本，Percona公司在MySQL社区版本的基础上增加了许多实用的功能和改进，比如线程池、InnoDB改进、问题诊断等等，本文将简单介绍Percona MySQL在慢查询日志方面的加强。

一、社区版MySQL慢查询日志有哪些不足？

在使用社区版MySQL时，是否存在这样的困惑，同样的一条SQL，为什么大多数时间执行正常，但是偶尔执行的非常慢？可能有很多原因导致SQL执行慢，但是从慢查询日志提供的信息，很难找出具体原因，比如来看下面两个测试案例。同样的一个SQL，两次执行耗时不一样。

第一次执行：

# 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);


第二次执行：

# 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);


从上面给出的慢查询日志，其中比较有用的一个信息是Rows_examined，但是两次执行的值是一样的，那么为什么Rows_examined一样的，执行耗时一个18.234596，另外一个2.681241，会相差这么多呢？导致差异的原因是什么？从现有的慢查询日志中，我们无法做出判断。

二、Percona MySQL 在慢查询日志上的加强

Percona Server for MySQL 扩展了慢查询日志功能，通过设置参数 log_slow_verbosity=full，能够在慢查询日志中打印更多的信息，有效地排查问题。同样的例子，在Percona MySQL中执行，会得到下面两个慢查询日志，如下：

第一次执行：

# 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);


第二次执行：

# 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);


相比于MySQL社区版，Percona MySQL的慢查询日志增加了很多额外的信息，从这些信息中，可以明显地看出差异在哪里，InnoDB IO相关的数值不一样，第一次执行慢，是因为需要从磁盘读取数据，第二次快，是因为数据都缓存在了buffer pool里面，没有磁盘IO的消耗。

除此之外，通过慢查询日志，还可以拿到类似于show profiling的详细信息，如下：

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);


三、减少慢查询日志对性能的影响

在一个繁忙的MySQL系统中，当我们设置 long_query_time=0 或者设置为一个较小的值时，可能会导致一秒内产生成千上万条慢查询日志，影响系统性能。因此Percona MySQL提供了两个参数来处理这种情况：

• log_slow_filter
• log_slow_rate_limit

例如只对join语句中没有使用索引的SQL记录到慢查询日志，或者设置每秒慢查询日志记录速度限制，比如像下面这样设置：

• log_slow_filter = full_join
• log_slow_rate_type = query
• log_slow_rate_limit = 100

这些设置都可以动态调整，可以在session级设置，也可以在全局设置。Percona 工具，比如 pt-query-digest 或者 Percona Monitoring and Management (PMM)，都能识别这些额外的慢查询日志信息。

四、MySQL 8.0 log_slow_extra

社区版 MySQL 8.0.14 版本增加了新的参数 log_slow_extra 用于扩展慢查询日志功能。这个参数与Percona MySQL 实现的扩展功能类似，两者可以同时打开。设置 log_slow_extra=1 之后，将会看到下面这样的慢查询日志：

# 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);


五、慢查询日志轮转

慢查询日志不断增长，如果没有自动日志轮转功能，处理一个大的慢查询日志文件将会非常困难，且占用大量磁盘空间。MySQL 5.7 版本提供了参数用于解决该问题，更轻松地管理慢查询日志：

• max_slowlog_size
• max_slowlog_files

然而这个功能及两个参数在Percona MySQL 8.0 被移除了，如果想要这个功能，只能期望MySQL官方来实现这个需求了，实际上在很久之前，就有人提过这个需求，并提交了path代码，然而这个功能直到现在也没有加入。

https://bugs.mysql.com/bug.php?id=38702