mysql:慢查詢日誌slow_query_log

一、慢查詢日誌：當查詢超過必定的時間沒有返回結果的時候，纔會記錄到慢查詢日誌中。默認不開啓。採樣的時候手工開啓。能夠幫助DBA找出執行慢的SQL語句

二、經常使用的參數詳解：

注意：修改如下參數，須要從新啓動數據庫服務纔會生效。
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所產生的慢查詢

三、不重啓修改慢查詢配置：

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);

四、經常使用慢查詢分析工具：

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