MySQL 的“慢查询”日志：奇怪的“Query_time”

Question

我需要一些帮助来了解我在 MySQL 中的“慢查询”日志发生了什么。我已经设定

 set global long_query_time=3

然而这是我在慢查询日志中看到的：

# Time: 120723  9:04:38
# User@Host: root[root] @  [111.111.111.205]
# Query_time: 0.017508  Lock_time: 0.000111 Rows_sent: 2884  Rows_examined: 9132
SET timestamp=1343027078;
SELECT [...]
# User@Host: root[root] @  [111.111.111.202]
# Query_time: 0.030282  Lock_time: 0.000102 Rows_sent: 0  Rows_examined: 12323
SET timestamp=1343027078;
SELECT [...]
# Time: 120723  9:04:41
# User@Host: root[root] @  [111.111.111.202]
# Query_time: 0.004416  Lock_time: 0.000104 Rows_sent: 18  Rows_examined: 6266
SET timestamp=1343027081;
SELECT [...]
# User@Host: root[root] @ hostname [111.111.111.199]
# Query_time: 0.029399  Lock_time: 0.000116 Rows_sent: 0  Rows_examined: 12323
SET timestamp=1343027088;
SELECT [...]
# Time: 120723  9:04:53
# User@Host: root[root] @  [111.111.111.201]
# Query_time: 0.004470  Lock_time: 0.000080 Rows_sent: 0  Rows_examined: 6248
SET timestamp=1343027093;
SELECT [...]
# Time: 120723  9:04:55
# User@Host: root[root] @  [111.111.111.198]
# Query_time: 0.042627  Lock_time: 0.000087 Rows_sent: 0  Rows_examined: 0
use [...];
SET timestamp=1343027095;
UPDATE [...]
# User@Host: root[root] @  [111.111.111.198]
# Query_time: 0.029115  Lock_time: 0.000124 Rows_sent: 0  Rows_examined: 0

Query_time 中的时间明显低于我之前指定的 3 秒。为什么？错过的时间在哪里？

MySQL 5.1.41，Ubuntu 10.04

Answer 1

啊，我应该先检查一下：

log_queries_not_using_indexes 已打开，因此已记录了大量查询，因为它们未使用索引。

显然，慢查询日志中没有以任何方式标记“不使用索引”的查询，因此必须猜测是否由于执行时间超过 long_query_time 阈值或因为索引而记录了条目。