MySQL -- 慢查询slow-query

慢查询的环境变量

slow_query_log: 是否启用慢查询日志，ON=启用，OFF=禁用；
slow_query_log_file: 慢查询日志的存放文件；

> show variables like '%slow_query%';
+---------------------+-----------------+
| Variable_name       | Value           |
+---------------------+-----------------+
| slow_query_log      | ON              |
| slow_query_log_file | armpvm-slow.log |
+---------------------+-----------------+
2 rows in set (0.001 sec)

long_query_time: 慢查询的时间阈值，单位s；

> show variables like '%long_query%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
+-----------------+----------+
1 row in set (0.001 sec)

log_queries_not_using_indexes：是否记录未使用索引的sql语句，记录=ON，不记录=OFF；

> show variables like '%log_queries%';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+
1 row in set (0.001 sec)

慢查询日志的统计分析

使用mysqldumpslow工具进行慢查询的统计分析：

# mysqldumpslow --help
Parse and summarize the MySQL slow query log. Options are


  --verbose    verbose
  --debug      debug
  --help       write this text to standard output


  -v           verbose
  -d           debug
  -s ORDER     what to sort by (aa, ae, al, ar, at, a, c, e, l, r, t), 'at' is default
                aa: average rows affected
                ae: aggregated rows examined
                al: average lock time
                ar: average rows sent
                at: average query time
                 a: rows affected
                 c: count
                 e: rows examined
                 l: lock time
                 r: rows sent
                 t: query time
  -r           reverse the sort order (largest last instead of first)
  -t NUM       just show the top n queries
  -a           don't abstract all numbers to N and strings to 'S'
  -n NUM       abstract numbers with at least n digits within names
  -g PATTERN   grep: only consider stmts that include this string
  -h HOSTNAME  hostname of db server for *-slow.log filename (can be wildcard),
               default is '*', i.e. match all
  -i NAME      name of server instance (if using mysql.server startup script)
  -l           don't subtract lock time from total time

按执行总时间，统计top 10的sql语句：

# mysqldumpslow -s t -t 10 armpvm-slow.log
.......

慢查询的查询计划分析

从慢查询日志中提取出sql语句，然后在环境上执行：

> explain select id from articles where title='One Life';
+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
| id   | select_type | table    | type | possible_keys | key  | key_len | ref  | rows | Extra       |
+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
|    1 | SIMPLE      | articles | ALL  | NULL          | NULL | NULL    | NULL |    4 | Using where |
+------+-------------+----------+------+---------------+------+---------+------+------+-------------+
1 row in set (0.001 sec)

查询计划中重点关注：

• key：使用的索引，若未使用则为null；
• rows：扫描的行数
• Extra: 额外的信息；

慢查询的各阶段时间消耗

一条查询语句：

• 首先经过查询缓存，若缓存命中，则直接返回；(查询缓存已Deprecated)
• 然后经过分析器，进行词法分析和语法分析；
• 然后经过优化器，生成执行计划，选择合适的索引；
• 最后经过执行器，调用存储引擎，返回结果。

使用profile查询各阶段时间消耗：

• 首先，set profiling=1，启动profile，这是一个session级别的配置；
• 然后，执行查询sql语句；
• 然后，show profiles，查看每一个查询所消耗的总时间信息；
• 最后，show profile for query N，查询某个sql语句详细的各阶段执行时间；

mysql> set session profiling = 1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show variables like '%profil%';
+------------------------+-------+
| Variable_name          | Value |
+------------------------+-------+
| have_profiling         | YES   |
| profiling              | ON    |
| profiling_history_size | 15    |
+------------------------+-------+
3 rows in set (0.01 sec)

mysql> select count(*) from film;
+----------+
| count(*) |
+----------+
|     1000 |
+----------+
1 row in set (0.01 sec)

mysql> show profiles;
+----------+------------+--------------------------------+
| Query_ID | Duration   | Query                          |
+----------+------------+--------------------------------+
|        1 | 0.00449100 | show variables like '%profil%' |
|        2 | 0.00254800 | select count(*) from film      |
+----------+------------+--------------------------------+
2 rows in set, 1 warning (0.00 sec)

mysql>
mysql> show profile for query 1;
+----------------------+----------+
| Status               | Duration |
+----------------------+----------+
| starting             | 0.001785 |
| checking permissions | 0.000020 |
| Opening tables       | 0.000019 |
| init                 | 0.000071 |
| System lock          | 0.000032 |
| optimizing           | 0.000007 |
| optimizing           | 0.000003 |
| statistics           | 0.000014 |
| preparing            | 0.000020 |
| statistics           | 0.000010 |
| preparing            | 0.000008 |
| executing            | 0.000010 |
| Sending data         | 0.000009 |
| executing            | 0.000004 |
| Sending data         | 0.002355 |
| end                  | 0.000030 |
| query end            | 0.000009 |
| closing tables       | 0.000005 |
| removing tmp table   | 0.000015 |
| closing tables       | 0.000011 |
| freeing items        | 0.000037 |
| cleaning up          | 0.000017 |
+----------------------+----------+
22 rows in set, 1 warning (0.00 sec)

mysql>

从上面的profile可以看出，耗时最长的是sending data，即server向client发送数据的过程。