mysql慢日志查询and简单分析

在对web系统的优化中，mysql数据库查询优化是比较重要的一部分。发现、分析和解决系统中昂贵的查询，我也来学一学。

mysql里面自带了慢查询日志功能，也就是记录下所有查询时间大于一定值的sql查询信息。

先检查一下慢查询日志是否打开。在mysql里面输入：show global variables like "%query%";

mysql> show global variables like "%query%";
+------------------------------+---------------------------------+
| Variable_name                | Value                           |
+------------------------------+---------------------------------+
| ft_query_expansion_limit     | 20                              |
| have_query_cache             | YES                             |
| long_query_time              | 1.000000                        |
| query_alloc_block_size       | 8192                            |
| query_cache_limit            | 1048576                         |
| query_cache_min_res_unit     | 4096                            |
| query_cache_size             | 33554432                        |
| query_cache_type             | ON                              |
| query_cache_wlock_invalidate | OFF                             |
| query_prealloc_size          | 8192                            |
| slow_query_log               | ON                              |
| slow_query_log_file          | /data/logs/mysql/mysql_slow.log |
+------------------------------+---------------------------------+
12 rows in set (0.00 sec)

如果slow_query_log是OFF，就需要配置一下my.cnf（安装目录etc下。注意这个配置文件也可能在/etc/my.cnf ）

配置选项设置慢查询时间为1秒：

slow_query_log = on
long_query_time = 1
slow_query_log_file = /data/logs/mysql/mysql_slow.log

然后重启下mysql服务：

service mysqld restart

慢查询功能就开启了奥。

以下是通过pt-query-digest工具来分析得到的日志文件。

首先安装一下下，在 http://www.percona.com/software/percona-toolkit 可以下载最新安装包。我下载的是2.2.10

wget http://www.percona.com/redir/downloads/percona-toolkit/LATEST/tarball/percona-toolkit-2.2.10.tar.gz
tar xvzf percona-toolkit-2.2.10.tar.gz
cd percona-toolkit-2.2.10
perl Makefile.PL
make && make install

安装完毕！可以在 /usr/local/bin 目录中看到pt-query-digest 。当然还有其他好几个工具，以后慢慢研究。

来看看日志：

./pt-query-digest /data/logs/mysql/mysql_slow.log 

# 290ms user time, 20ms system time, 21.52M rss, 172.95M vsz
# Current date: Tue Sep 16 21:56:06 2014
# Hostname: test-204.92
# Files: /data/logs/mysql/mysql_slow.log
# Overall: 11 total, 1 unique, 0 QPS, 0x concurrency _____________________
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time            28s      2s      5s      3s      5s      1s      2s
# Lock time              0       0       0       0       0       0       0
# Rows sent             11       1       1       1       1       0       1
# Rows examine           0       0       0       0       0       0       0
# Query size           165      15      15      15      15       0      15

# Profile
# Rank Query ID           Response time  Calls R/Call V/M   Item
# ==== ================== ============== ===== ====== ===== ======
#    1 0xF9A57DD5A41825CA 28.0026 100.0%    11 2.5457  0.53 SELECT

# Query 1: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 0 ________
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.53
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count        100      11
# Exec time    100     28s      2s      5s      3s      5s      1s      2s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent    100      11       1       1       1       1       0       1
# Rows examine   0       0       0       0       0       0       0       0
# Query size   100     165      15      15      15      15       0      15
# String:
# Databases    test2
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(5)\G

其中rank query id 列出了前几个昂贵查询。后面则显示了查询的详细信息和查询语句，这样还能通过explain方法运行语句，进一步改进这些查询语句了。

pt-query-digest更多选项，查看pt-query-digest --help