MySQL慢查询日志(二)

原创

aklaus 2015-04-16 20:26:33 博主文章分类：MySQL DBA ©著作权

文章标签 mysql 慢查询 slow_query_log 文章分类 MySQL 数据库

©著作权归作者所有：来自51CTO博客作者aklaus的原创作品，谢绝转载，否则将追究法律责任

慢查询日志用来优化Query语句，以下是有关的几个参数，5.5版本以后可以到微秒（μs）新版本中还有long_query_io(读取次数) log_queries_not_using_indexes(没有使用索引的SQL) log_throttle_not_using_indexes(控制每分钟不实用索引SQL记录的次数)

[root@hack data]# mysqldumpslow --help 常用的解释一下
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]
-s ORDER （可以根据查询时间、行数、锁定时间，总数及他们的平均值）

what to sort by (al, at, ar, c, l, r, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                 c: count
                 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
-g PATTERN（用来过滤） grep: only consider stmts that include this string
eg：查询最慢执行时间最慢的10条？？？？？？？？

针对mysqldumpslow的输出做个说明

[root@hack data]# mysqldumpslow hack-slow.log 这个是我的输出
Reading mysql slow query log from hack-slow.log
Count: 5 Time=0.01s (0s) Lock=0.00s (0s) Rows=128.8 (644), root[root]@localhost
select * from ssq where s2 =N limit N
[root@hack data]#
下面进行说明：

Count 是我执行了五次这样的query，

select * from ssq where s2 =2 limit 123

select * from ssq where s2 =4 limit 123

认为是这种类型：select * from ssq where s2 =N limit N所以认为是一样的

Time 执行这类query的时候的平均时间（0）s Lock Rows 同样如此

[root@hack data]# mysqldumpslow -s r -t 10 hack-slow.log
#我是按返回的行数进行的排序可以看到是用的Rows括号的值，如果用外面的就用参数ar
Reading mysql slow query log from hack-slow.log
Count: 1 Time=25.94s (25s) Lock=0.00s (0s) Rows=47823.0 (47823), root[root]@localhost
select * from t
Count: 1 Time=0.03s (0s) Lock=0.00s (0s) Rows=1225.0 (1225), root[root]@localhost
select * from dlt
Count: 5 Time=0.01s (0s) Lock=0.00s (0s) Rows=128.8 (644), root[root]@localhost
select * from ssq where s2 =N limit N
Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=234.0 (234), root[root]@localhost
select * from dlt limit N
Count: 1 Time=0.01s (0s) Lock=0.00s (0s) Rows=146.0 (146), root[root]@localhost

[root@hack data]# mysqldumpslow -s at -t 10 hack-slow.log
#用at排序

Reading mysql slow query log from hack-slow.log
Count: 1 Time=25.94s (25s) Lock=0.00s (0s) Rows=47823.0 (47823), root[root]@localhost
select * from t
Count: 1 Time=0.03s (0s) Lock=0.00s (0s) Rows=1225.0 (1225), root[root]@localhost
select * from dlt
Count: 5 Time=0.01s (0s) Lock=0.00s (0s) Rows=128.8 (644), root[root]@localhost
select * from ssq where s2 =N limit N

[root@hack data]# tail -f hack-slow.log
Tcp port: 3306 Unix socket: /usr/local/mysql/mysql.sock
Time                 Id Command    Argument
/usr/local/mysql/bin/mysqld, Version: 5.6.14-log (Source distribution). started with:
Tcp port: 3306 Unix socket: /usr/local/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 150417 1:23:49
# User@Host: root[root] @ localhost [] Id:     1
# Query_time: 0.118892 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0
SET timestamp=1429205029;
select version();
# Time: 150417 1:24:20
# User@Host: root[root] @ localhost [] Id:     1
# Query_time: 0.426234 Lock_time: 0.139966 Rows_sent: 5 Rows_examined: 5
SET timestamp=1429205060;
show variables like '%slow%';
^C
另外从5.1版本之后，开始慢查询日志可以记录到数据库中，在mysql中存在一个slow_log的表

mysql> show create table mysql.slow_log \G
*************************** 1. row ***************************
Table: slow_log
Create Table: CREATE TABLE `slow_log` (
`start_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`user_host` mediumtext NOT NULL,
`query_time` time NOT NULL,
`lock_time` time NOT NULL,
`rows_sent` int(11) NOT NULL,
`rows_examined` int(11) NOT NULL,
`db` varchar(512) NOT NULL,
`last_insert_id` int(11) NOT NULL,
`insert_id` int(11) NOT NULL,
`server_id` int(10) unsigned NOT NULL,
`sql_text` mediumtext NOT NULL,
`thread_id` bigint(21) unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8 COMMENT='Slow log'
1 row in set (0.07 sec)
mysql> 可以看到该表的引擎为CSV

mysql> show variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE |
+---------------+-------+
1 row in set (0.03 sec)
mysql> set global log_output='FILE,TABLE';更改日志输出到文件和表中
Query OK, 0 rows affected (0.07 sec)
mysql> show variables like '%log_output%';
+---------------+------------+
| Variable_name | Value      |
+---------------+------------+
| log_output    | FILE,TABLE |
+---------------+------------+
1 row in set (0.09 sec)

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

mysql> select * from mysql.slow_log \G 我从打开table到查询有两条语句达到慢查询设定的时间
*************************** 1. row ***************************
    start_time: 2015-04-17 01:33:50
     user_host: root[root] @ localhost []
    query_time: 00:00:00
     lock_time: 00:00:00
     rows_sent: 0
rows_examined: 0
            db:
last_insert_id: 0
     insert_id: 0
     server_id: 13
      sql_text: set global log_output='FILE,TABLE'
     thread_id: 1
*************************** 2. row ***************************
    start_time: 2015-04-17 01:34:17
     user_host: root[root] @ localhost []
    query_time: 00:00:10
     lock_time: 00:00:00
     rows_sent: 1
rows_examined: 0
            db:
last_insert_id: 0
     insert_id: 0
     server_id: 13
      sql_text: select sleep(10)
     thread_id: 1
2 rows in set (0.01 sec)

mysql> 修改slow_log的存储引擎为myisam

mysql> alter table mysql.slow_log engine=myisam;
ERROR 1580 (HY000): You cannot 'ALTER' a log table if logging is enabled
mysql> set global slow_query_log=off;
Query OK, 0 rows affected (0.00 sec)

mysql> alter table mysql.slow_log engine=myisam;
Query OK, 3 rows affected (0.15 sec)
Records: 3 Duplicates: 0 Warnings: 0

mysql>