mysql:慢查询日志slow_query_log

1、慢查询日志：当查询超过一定的时间没有返回结果的时候，才会记录到慢查询日志中。默认不开启。采样的时候手工开启。可以帮助DBA找出执行慢的SQL语句

2、常用的参数详解：

注意：修改以下参数，需要重新启动数据库服务才会生效。
slow_query_log=off|on     --是否开启慢查询日志
slow_query_log_file=filename --指定保存路径及文件名，默认为数据文件目录，hostname-slow.log
long_query_time=2    --指定多少秒返回查询的结果为慢查询
long-queries-not-using-indexes　　 --记录所有没有使用到索引的查询语句
min_examined_row_limit=1000　　　　--记录那些由于查找了多余1000次而引发的慢查询
long-slow-admin-statements　　　　 --记录那些慢的optimize table，analyze table和alter table语句
log-slow-Slave-statements　　　　  --记录由Slave所产生的慢查询

3、不重启修改慢查询配置：

set @@global.slow_query_log=1
set @@global.slow_query_time=3
其他参数可通过以下命令查阅：
show variables  '%slow%';

mysql> show variables like '%slow%';
+---------------------------+-----------------------------------+
| Variable_name             | Value                             |
+---------------------------+-----------------------------------+
| log_slow_admin_statements | OFF                               |
| log_slow_slave_statements | OFF                               |
| slow_launch_time          | 2                                 |
| slow_query_log            | OFF                               |
| slow_query_log_file       | /var/lib/mysql/localhost-slow.log |
+---------------------------+-----------------------------------+
mysql> show variables like '%long%';
+--------------------------------------------------------+-----------+
| Variable_name                                          | Value     |
+--------------------------------------------------------+-----------+
| long_query_time                                        | 10.000000 |
| performance_schema_events_stages_history_long_size     | 10000     |
| performance_schema_events_statements_history_long_size | 10000     |
| performance_schema_events_waits_history_long_size      | 10000     |
+--------------------------------------------------------+-----------+
4 rows in set (0.03 sec)

mysql> show variables like '%min%';
+---------------------------+-------+
| Variable_name             | Value |
+---------------------------+-------+
| ft_min_word_len           | 4     |
| innodb_ft_min_token_size  | 3     |
| log_slow_admin_statements | OFF   |
| min_examined_row_limit    | 0     |
| query_cache_min_res_unit  | 4096  |
+---------------------------+-------+
5 rows in set (0.00 sec)

EG:开启慢查询日志：示例

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.08 sec)
mysql> set global long_query_time=2;
Query OK, 0 rows affected (0.00 s
mysql> set  long_query_time=2;
Query OK, 0 rows affected (0.05 sec)

[root@localhost mysql]# ls
auto.cnf  ib_logfile0  king                       localhost.log       mysql             mysql_bin.000002  mysql_bin.000004  mysql_bin.index  performance_schema  utf8
ibdata1   ib_logfile1  localhost.localdomain.pid  localhost-slow.log  mysql_bin.000001  mysql_bin.000003  mysql_bin.000005  mysql.sock       test                world

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select sleep(4);
+----------+
| sleep(4) |
+----------+
|        0 |
+----------+
1 row in set (4.01 sec)

[root@localhost mysql]# tail -f localhost-slow.log 
/usr/local/mysql/bin/mysqld, Version: 5.6.23-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 160328 11:31:47
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 3.000955  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
use king;
SET timestamp=1459135907;
select sleep(3);
# Time: 160328 11:31:57
# User@Host: root[root] @ localhost []  Id:     4
# Query_time: 4.001169  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1459135917;
select sleep(4);

4、常用慢查询分析工具：

mysqldumpslow（结果简陋不方便阅读分析）

mysqlsla

percona-toolkit中的pt-query-digest

[root@localhost mysql]# mysqldumpslow localhost-slow.log 

Reading mysql slow query log from localhost-slow.log
Count: 2  Time=3.50s (7s)  Lock=0.00s (0s)  Rows=1.0 (2), root[root]@localhost
  select sleep(N)

[root@localhost log]# chmod +x mysqlsla-2.03 
[root@localhost log]# ll
总用量 1824
-rwxr-xr-x. 1 root root  105463 11月 11 2008 mysqlsla-2.03
-rw-r--r--. 1 root root 1760229 4月  18 2014 percona-toolkit-2.2.7-1.noarch.rpm
[root@localhost log]# ./mysqlsla-2.03 /var/lib/mysql/localhost-slow.log 
Auto-detected logs as slow logs
Report for slow logs: /var/lib/mysql/localhost-slow.log
2 queries total, 1 unique
Sorted by 't_sum'
Grand Totals: Time 7 s, Lock 0 s, Rows sent 2, Rows Examined 0


______________________________________________________________________ 001 ___
Count         : 2  (100.00%)
Time          : 7.002124 s total, 3.501062 s avg, 3.000955 s to 4.001169 s max  (100.00%)
Lock Time (s) : 0 total, 0 avg, 0 to 0 max  (0.00%)
Rows sent     : 1 avg, 1 to 1 max  (100.00%)
Rows examined : 0 avg, 0 to 0 max  (0.00%)
Database      : king
Users         : 
    root@localhost  : 100.00% (2) of query, 100.00% (2) of all users

Query abstract:
SET timestamp=N; SELECT sleep(N);

Query sample:
SET timestamp=1459135907;
select sleep(3);

[root@localhost log]# rpm -ivh percona-toolkit-2.2.7-1.noarch.rpm --nodeps
Preparing...                ########################################### [100%]
   1:percona-toolkit        ########################################### [100%]
[root@localhost log]# pt-query-digest /var/lib/mysql/localhost-slow.log 

# A software update is available:
#   * The current version for Percona::Toolkit is 2.2.14.


# 820ms user time, 390ms system time, 21.98M rss, 177.44M vsz
# Current date: Mon Mar 28 11:50:37 2016
# Hostname: localhost.localdomain
# Files: /var/lib/mysql/localhost-slow.log
# Overall: 2 total, 1 unique, 0.20 QPS, 0.70x concurrency ________________
# Time range: 2016-03-28 11:31:47 to 11:31:57
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time             7s      3s      4s      4s      4s   707ms      4s
# Lock time              0       0       0       0       0       0       0
# Rows sent              2       1       1       1       1       0       1
# Rows examine           0       0       0       0       0       0       0
# Query size            30      15      15      15      15       0      15

# Profile
# Rank Query ID           Response time Calls R/Call V/M   Item
# ==== ================== ============= ===== ====== ===== ======
#    1 0xF9A57DD5A41825CA 7.0021 100.0%     2 3.5011  0.14 SELECT

# Query 1: 0.20 QPS, 0.70x concurrency, ID 0xF9A57DD5A41825CA at byte 397
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.14
# Time range: 2016-03-28 11:31:47 to 11:31:57
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count        100       2
# Exec time    100      7s      3s      4s      4s      4s   707ms      4s
# Lock time      0       0       0       0       0       0       0       0
# Rows sent    100       2       1       1       1       1       0       1
# Rows examine   0       0       0       0       0       0       0       0
# Query size   100      30      15      15      15      15       0      15
# String:
# Databases    king
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s  ################################################################
#  10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(4)G