mysql - 如何解读MySQL产生的慢查询日志信息？

Question

所以我对慢查询日志的理解是，它记录了我们在 my.conf 文件中设置的所有花费 >= 时间(以秒为单位)的查询的信息。

现在让我们采用 3 个不同的 SELECT 查询的 3 个案例(针对具有 INNODB 引擎的表):

QUERY I: Query_time:32.937667 Lock_time:0.000081 Rows_sent:343 Rows_examined: 12714043

QUERY II: Query_time: 12.937667 Lock_time: 0.000081 Rows_sent: 43 Rows_examined: 714043

QUERY III: Query_time:42.937667 Lock_time:0.000081 Rows_sent:18 Rows_examined:483

对我来说，QUERY I 和 QUERY II 看起来都可能是查询错误或索引不佳(或缺少索引)或碎片表数据等(我可能遗漏的任何其他情况？)，用户可能会考虑改进查询执行时间。

但是对于 QUERY III，我无法理解，我的意思是数据库可能真的出了什么问题，它需要 42 秒才能检查 483 行并发回其中的 18 行(锁定可以忽略不计)时间)。当我看到它间歇性发生时，这变得更加令人困惑。

所以我在这里真正想问的是:

• 我应该如何解释锁定时间信息？这是否意味着查询必须等待那么多秒才能真正开始执行？如果是，那么在我的示例查询 III 中实际上花费了 42 秒来检查 483 行并发回其中的 18 行？
• 如果锁定时间可以忽略不计，但查询时间仍然非常巨大，只有几百行被检查并发回，我应该从哪里开始寻找问题？
• 可能是查询在某些后台 IO 事件中花费了很多时间吗？说日志或 bin-logging。
• 表大小对查询性能的影响有多大？例如我们可以说 MySQL 足以处理 200+ 百万行的表吗
• 有没有更好的工具或方法来专门监控数据库事件以了解数据库的后台事件？简而言之，检查查询花费大部分时间的地方。

可能有很多因素会影响这种缓慢的查询，所以如果您觉得需要更多信息来帮助我，请告诉我。

Answer 1

• 锁定时间是查询开始执行之前所花费的时间。即，等待其他线程放弃对当前查询需要锁定的数据的锁定的时间。

• 查询时间是执行查询的时间。如果行不在缓冲池中，这可能涉及等待 I/O。在数据加载到缓冲池之后，对相同的数据重复相同的查询可能会更快。

  如果您的查询是针对给定查询在磁盘上排序，即使它检查几行也会变慢。

  如果您的 I/O 系统负担过重，您可能会遇到间歇性缓慢。这也可能发生在虚拟化 I/O(例如，廉价的 AWS 实例)上。或者，如果您的磁盘开始出现故障，它们可能会间歇性地出错。

  监控 iostat 并观察队列长度、平均等待时间和服务时间。看看是否有缓慢的时期，或者性能和吞吐量是否或多或少一致。

• 检查的行数不反射(reflect)获取给定行所需的多个 I/O。例如，如果该行有很多大的 BLOB/TEXT/VARCHAR 列存储在溢出页上。或者，如果事务需要访问回滚段以获取某些行的旧版本，如果它们在此事务开始后已被修改。

  检查的行数也不能告诉我们查询中的表达式有多复杂。您可能正在计算 Fibonacci sequences in stored functions或类似的疯狂的东西。

  如果没有看到查询及其 EXPLAIN 报告，很难概括解释缓慢的原因，仅给出慢查询日志中的那些数字。

MySQL 当然可以在一个表中存储 2 亿行，但在那个规模下，即使索引可以将搜索减少到 483 行检查，您也会开始遇到性能问题。那是因为 depth of the B-tree index and size of an indexed column与查找这 483 行所需的 I/O 操作数直接相关。 I/O 越多，花费的时间就越长，这并没有反射(reflect)在检查的行中。查询时间包括 I/O 时间，但并不清楚查询时间有多少是由于 I/O 造成的。

寻找更详细诊断的其他一些地方是:

• MySQL Performance Schema

• MySQL Query Profiler (但请注意，不赞成使用性能模式)

• Enhanced verbosity slow query log in Percona Server报告查询等待 I/O 所花费的时间。