乐趣区

关于mysql:MySQL-慢查询slowquery

jiezi

慢查问的环境变量

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 发送数据的过程。

退出移动版