mysql 慢日志 逻辑读_学会读懂 MySql 的慢查询日志

在前边的博客《何时、怎样开启 MySql 日志？》中，我们了解到了怎样启用 MySql 的慢查询日志。

今天我们来看一下怎样去读懂这些慢查询日志。

在跟踪慢查询日志之前。首先你得保证最少发生过一次慢查询。假设你没有能够自己制造一个：

root@server# mysql -e 'SELECT SLEEP(8);

上述操作所做的事情仅仅有一个："睡"(啥也不做)八秒。这个长度应该足以被记录在你的慢查询日志里了(我通常推荐针对长于 2 或 3 秒的查询进行慢查询记录)。

首先，我们看看一个慢速查询日志条目是什么样子的：

root@server# tail /var/log/slowqueries

# Time: 130320  7:30:26

# User@Host: db_user[db_database] @ localhost []

# Query_time: 4.545309  Lock_time: 0.000069 Rows_sent: 219  Rows_examined: 254

SET timestamp=1363779026;

SELECT option_name, option_value FROM wp_options WHERE autoload = 'yes';

我们来过一下每一行所代表的意思：第一行表示记录日志时的时间。其格式是 YYMMDD H:M:S。我们能够看出上面的查询记录于 2013 年 3 月 20 日上午 7:30 - 注意：这个是server时间，可能跟你本地时间有所不同

然后，我们能够看到 MySql 用户、server以及主机名

第三行表示总的查询时间、锁定时间、"发送"或者返回的行数、查询过程中所检查的行数

接下来我们看到的是 SET timestamp=UNIXTIME; 这是查询实际发生的时间。假设你想找如今的一些慢查询。通过检查这个就不会发生你所检查的是几个月之前所发生的慢查询了。下边我会介绍怎样将其变成一个实用的时间

最后一行显示完整的查询语句要将 Unix 时间转成一个人类可读的时间，能够使用 date -d 命令。

输入 date -d @(记得要包含 @ 符号)，然后在 @(之间没有空格)后粘贴日志中的时间戳：

root@server# date -d @1363779026

Wed Mar 20 07:30:26 EDT 2013

上面样例中我们能够看到查询进行的同一时候记录了该日志 - 可是对于一台超负载的server经常并不是如此。

因此记住：SET timestamp= value 才是实际的查询的执行时间。

如今我来演示一下我是怎样使用 MySql 慢查询日志来解决我的某个站点上的一个真实问题的。

你的查询可能与此不太一样，可是解决这个问题的原理是相通的。

我在一个博客站点上使用了一个名为 Tweet Blender 的插件来自己主动显示相关微博到我的keyword中。不幸的是，一些人发现了这个并使用我的微博中的keyword来发一些垃圾微博 - 无论怎样，终于结果就是我的博客站点上显示的是一些垃圾微博。

由于相关微博在我的站点存在的时间并不长，所以我在站点上并没有发现什么问题。直到我查看慢查询日志。

我的站点对带有垃圾信息(垃圾信息经常都是一样的)的微博进行了几个相似的查询，经过一段时间后这些查询的数量太大以致当中的一些执行迟缓。

当这样的情况发生的时候，由于请求的数量非常大，有些朋友的站点非常可能会因此假死或者直接报错。可是我的server经过非常好的性能调优，因此并没有非常明显的影响。幸运的是当时我正在进行慢查询日志查看。及时发现了这一情况并迅速攻克了这个问题。

这个问题的解决非常easy - Tweet Blender 具备一个美丽的过滤功能。我仅仅需将该微博username以及一些垃圾keyword加入到 "exclude" 列表。之后就再也没有这样的问题了。这样看来，对我们自己站点以及日志的监控是多么重要，即使是一星期对每一个站点/server仅仅进行一次高速检查。