学会读懂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 - 注意：这个是服务器时间，可能跟你本地时间有所不同然后，我们可以看到 MySql 用户、服务器以及主机名第三行表示总的查询时间、锁定时间、"发送"或者返回的行数、查询过程中所检查的行数接下来我们看到的是 SET timestamp=UNIXTIME; 这是查询实际发生的时间。如果你想找现在的一些慢查询，通过检查这个就不会发生你所检查的是几个月之前所发生的慢查询了。下边我会介绍如何将其变成一个有用的时间最后一行显示完整的查询语句要将 Unix 时间转成一个人类可读的时间，可以使用 date -d 命令。输入 date -d @(记得要包括 @ 符号)，然后在 @(之间没有空格)后粘贴日志中的时间戳：
root@server# date -d @1363779026
Wed Mar 20 07:30:26 EDT 2013
上面例子中我们可以看到查询进行的同时记录了该日志 - 但是对于一台超负载的服务器常常并非如此。因此记住：SET timestamp= value 才是实际的查询的执行时间。

现在我来演示一下我是如何使用 MySql 慢查询日志来解决我的某个网站上的一个真实问题的。你的查询可能与此不太一样，但是解决问题的原理是相通的。

我在一个博客网站上使用了一个名为 Tweet Blender 的插件来自动显示相关微博到我的关键字中。不幸的是，一些人发现了这个并使用我的微博中的关键字来发一些垃圾微博 - 不管怎样，最终结果就是我的博客网站上显示的是一些垃圾微博。因为相关微博在我的网站存在的时间并不长，所以我在网站上并没有发现什么问题，直到我查看慢查询日志。
我的网站对带有垃圾信息(垃圾信息常常都是一样的)的微博进行了几个类似的查询，经过一段时间后这些查询的数量太大以致其中的一些运行迟缓。当这种情况发生的时候，由于请求的数量非常大，有些朋友的网站很可能会因此假死或者直接报错，但是我的服务器经过很好的性能调优，因此并没有很明显的影响。幸运的是当时我正在进行慢查询日志查看，及时发现了这一情况并迅速解决了这个问题。
这个问题的解决很简单 - Tweet Blender 具备一个漂亮的过滤功能，我只需将该微博用户名以及一些垃圾关键字添加到 "exclude" 列表，之后就再也没有这种问题了。这样看来，对我们自己网站以及日志的监控是多么重要，即使是一星期对每个站点/服务器只进行一次快速检查。