MySQL 慢查询日志(Slow Query Log)

    同大多数关系型数据库一样，日志文件是MySQL数据库的重要组成部分。MySQL有几种不同的日志文件，通常包括错误日志文件，二进制日志，通用日志，慢查询日志，等等。这些日志可以帮助我们定位mysqld内部发生的事件，数据库性能故障，记录数据的变更历史，用户恢复数据库等等。本文主要描述通用查询日志。

 

1、MySQL日志文件系统的组成
   a、错误日志：记录启动、运行或停止mysqld时出现的问题。
   b、通用日志：记录建立的客户端连接和执行的语句。
   c、更新日志：记录更改数据的语句。该日志在MySQL 5.1中已不再使用。
   d、二进制日志：记录所有更改数据的语句。还用于复制。
   e、慢查询日志：记录所有执行时间超过long_query_time秒的所有查询或不使用索引的查询。
   f、Innodb日志：innodb redo log
   
   缺省情况下，所有日志创建于mysqld数据目录中。
   可以通过刷新日志，来强制mysqld来关闭和重新打开日志文件（或者在某些情况下切换到一个新的日志）。
   当你执行一个FLUSH LOGS语句或执行mysqladmin flush-logs或mysqladmin refresh时，则日志被老化。
   对于存在MySQL复制的情形下，从复制服务器将维护更多日志文件，被称为接替日志。

 

2、慢查询日志
   慢查询日志是将mysql服务器中影响数据库性能的相关SQL语句记录到日志文件，通过对这些特殊的SQL语句分析，改进以达到提高数据库性能的目的。
   通过使用--slow_query_log[={0|1}]选项来启用慢查询日志。所有执行时间超过long_query_time秒的SQL语句都会被记录到慢查询日志。
   缺省情况下hostname-slow.log为慢查询日志文件安名，存放到数据目录，同时缺省情况下未开启慢查询日志。
   缺省情况下数据库相关管理型SQL(比如OPTIMIZE TABLE、ANALYZE TABLE和ALTER TABLE)不会被记录到日志。
   对于管理型SQL可以通过--log-slow-admin-statements开启记录管理型慢SQL。
   mysqld在语句执行完并且所有锁释放后记入慢查询日志。记录顺序可以与执行顺序不相同。获得初使表锁定的时间不算作执行时间。
   
   可以使用mysqldumpslow命令获得日志中显示的查询摘要来处理慢查询日志。
   用查询缓存处理的查询不加到慢查询日志中，表有零行或一行而不能从索引中受益的查询也不写入慢查询日志。
   MySQL服务器按以下顺序记录SQL是否写入到慢查询日志
     a. The query must either not be an administrative statement, or --log-slow-adminstatements must have been specified.
     b. The query must have taken at least long_query_time seconds, or log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.
     c. The query must have examined at least min_examined_row_limit rows.
     d. The query must not be suppressed according to the log_throttle_queries_not_using_indexes setting.

 

3、慢查询日志演示

long_query_time     ：  设定慢查询的阀值，超出次设定值的SQL即被记录到慢查询日志，缺省值为10s
slow_query_log      ：  指定是否开启慢查询日志
log_slow_queries    ：  指定是否开启慢查询日志(该参数要被slow_query_log取代，做兼容性保留)
slow_query_log_file ：  指定慢日志文件存放位置，可以为空，系统会给一个缺省的文件host_name-slow.log
min_examined_row_limit：查询检查返回少于该参数指定行的SQL不被记录到慢查询日志
log_queries_not_using_indexes: 不使用索引的慢查询日志是否记录到索引

--当前版本
root@localhost[(none)]> show variables like 'version';
+---------------+------------+
| Variable_name | Value      |
+---------------+------------+
| version       | 5.5.39-log |
+---------------+------------+

root@localhost[(none)]> show variables like '%slow%';
+---------------------+---------------------------------+
| Variable_name       | Value                           |
+---------------------+---------------------------------+
| log_slow_queries    | OFF                             |
| slow_launch_time    | 2                               |
| slow_query_log      | OFF                             |
| slow_query_log_file | /var/lib/mysql/suse11b-slow.log |
+---------------------+---------------------------------+

root@localhost[tempdb]> set global log_slow_queries=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

root@localhost[(none)]> show warnings;
+---------+------+-------------------------------------------------------------------------------------------------------------------+
| Level   | Code | Message                                                                                                           |
+---------+------+-------------------------------------------------------------------------------------------------------------------+
| Warning | 1287 | '@@log_slow_queries' is deprecated and will be removed in a future release. Please use '@@slow_query_log' instead |
+---------+------+-------------------------------------------------------------------------------------------------------------------+

--从下面的查询中可知，2个系统变量log_slow_queries，slow_query_log同时被置为on
root@localhost[(none)]> show variables like '%slow%';
+---------------------+---------------------------------+
| Variable_name       | Value                           |
+---------------------+---------------------------------+
| log_slow_queries    | ON                              |
| slow_launch_time    | 2                               |
| slow_query_log      | ON                              |
| slow_query_log_file | /var/lib/mysql/suse11b-slow.log |
+---------------------+---------------------------------+

root@localhost[tempdb]> show variables like '%long_query_time%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+

--为便于演示，我们将全局和session级别long_query_time设置为1
root@localhost[tempdb]> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)

root@localhost[tempdb]> set session long_query_time=1;
Query OK, 0 rows affected (0.00 sec)

--Author : Leshami
--Blog   : http://blog.csdn.net/leshami

root@localhost[tempdb]> create table tb_slow as select * from information_schema.columns;
Query OK, 829 rows affected (0.10 sec)
Records: 829  Duplicates: 0  Warnings: 0

root@localhost[tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 829 rows affected (0.05 sec)
Records: 829  Duplicates: 0  Warnings: 0
       .....为便于演示，我们插入一些数据，中间重复过程省略
root@localhost[tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 26528 rows affected (4.40 sec)
Records: 26528  Duplicates: 0  Warnings: 0

root@localhost[tempdb]> system tail  /var/lib/mysql/suse11b-slow.log
/usr/sbin/mysqld, Version: 5.5.39-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
Time                 Id Command    Argument
# Time: 141004 22:05:48
# User@Host: root[root] @ localhost []
# Query_time: 4.396858  Lock_time: 0.000140 Rows_sent: 0  Rows_examined: 53056
use tempdb;
SET timestamp=1412431548;
insert into tb_slow select * from tb_slow;

    ....再次插入一些记录....
root@localhost[tempdb]> insert into tb_slow select * from tb_slow;
Query OK, 212224 rows affected (37.51 sec)
Records: 212224  Duplicates: 0  Warnings: 0

root@localhost[tempdb]> select table_schema,table_name,count(*) from tb_slow
    -> group by table_schema,table_name order by 3,2;
+--------------------+----------------------------------------------+----------+
| table_schema       | table_name                                   | count(*) |
+--------------------+----------------------------------------------+----------+
| information_schema | COLLATION_CHARACTER_SET_APPLICABILITY        |     1024 |
| performance_schema | cond_instances                               |     1024 |
                  ...........
| mysql              | user                                         |    21504 |
+--------------------+----------------------------------------------+----------+
83 rows in set (1.58 sec)                  

root@localhost[tempdb]> system tail  /var/lib/mysql/suse11b-slow.log
# User@Host: root[root] @ localhost []
# Query_time: 37.514172  Lock_time: 0.000123 Rows_sent: 0  Rows_examined: 424448
SET timestamp=1412431806;
insert into tb_slow select * from tb_slow;
# Time: 141004 22:10:47
# User@Host: root[root] @ localhost []
# Query_time: 1.573293  Lock_time: 0.000183 Rows_sent: 83  Rows_examined: 424614
SET timestamp=1412431847;
select table_schema,table_name,count(*) from tb_slow  --这条SQL被记录下来了，其查询时间为1.573293s
group by table_schema,table_name order by 3,2;

root@localhost[tempdb]> show variables like '%log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+

root@localhost[tempdb]> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)

--查看表tb_slow索引信息，表tb_slow无任何索引
root@localhost[tempdb]> show index from tb_slow;
Empty set (0.00 sec)

root@localhost[tempdb]> select count(*) from tb_slow;
+----------+
| count(*) |
+----------+
|   424448 |
+----------+
1 row in set (0.20 sec)

root@localhost[tempdb]> system tail -n3 /var/lib/mysql/suse11b-slow.log
# Query_time: 0.199840  Lock_time: 0.000152 Rows_sent: 1  Rows_examined: 424448
SET timestamp=1412432188;
select count(*) from tb_slow;   --此次查询时间为0.199840，被记录的原因是因为没有走索引，因为表本身没有索引

4、格式化慢查询日志

结构化慢查询日志就是把慢查询日志中的重要信息按照便于阅读以及按照特定的排序方式来提取SQL。
这种方式有点类似于Oracle中有个tkprof来格式化oracle的trace文件。
对于前面的慢查询日志我们使用mysqldumpslow来提取如下：

suse11b:~ # mysqldumpslow -s at,al /var/lib/mysql/suse11b-slow.log
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
Count: 4  Time=16.87s (67s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into tb_slow select * from tb_slow

Count: 1  Time=0.20s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select count(*) from tb_slow

Count: 1  Time=1.57s (1s)  Lock=0.00s (0s)  Rows=83.0 (83), root[root]@localhost
  select table_schema,table_name,count(*) from tb_slow
  group by table_schema,table_name order by N,N

#以下是按照最大耗用时间排最后，只显示2条的方式格式化日志文件
suse11b:~ # mysqldumpslow -r -t 2 /var/lib/mysql/suse11b-slow.log
Reading mysql slow query log from /var/lib/mysql/suse11b-slow.log
Count: 1  Time=1.57s (1s)  Lock=0.00s (0s)  Rows=83.0 (83), root[root]@localhost
  select table_schema,table_name,count(*) from tb_slow
  group by table_schema,table_name order by N,N

Count: 4  Time=16.87s (67s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  insert into tb_slow select * from tb_slow

#获取mysqldumpslow的帮助信息
suse11b:~ # mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

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 (al, at, ar, c, l, r, t), 'at' is default
                al: average lock time
                ar: average rows sent
                at: average query time
                 c: count        #query的次数
                 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

时间： 2024-08-02 18:57:43

MySQL 慢查询日志(Slow Query Log)的相关文章

mysql中slow query log慢日志查询分析

一.慢查询日志 配置 开启慢查询日志 , 配置样例: /etc/mysql/my.cnf [mysqld] log-slow-queries 在 my.cnf 配置文件中增加上述配置项并重启 mysql 服务,这时 mysql 慢查询功能生效.慢查询 日志将写入参数 DATADIR (数据目录:/var/lib/mysql) 指定的路径下,默认文件名是 host_name-slow.log . 和错误日志.查询日志一样,慢查询日志记录的格式也是纯文本,可以被直接读取.下例中演示了慢查询日志的设置

MySQL慢查询日志总结

慢查询日志概念      MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_query_time值的SQL,则会被记录到慢查询日志中.long_query_time的默认值为10,意思是运行10S以上的语句.默认情况下,Mysql数据库并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是调优需要的话,一般不建议启动该参数,因为开启慢查询日志会或多或少带来一定的性能影响.慢查询日志支持将日志记录写入文件,也支

mysql慢查询日志分析实例

1.MySQL 慢查询日志分析 pt-query-digest分析慢查询日志 pt-query-digest –report slow.log 报告最近半个小时的慢查询: pt-query-digest –report –since 1800s slow.log 报告一个时间段的慢查询: pt-query-digest –report –since '2013-02-10 21:48:59′ –until '2013-02-16 02:33:50′ slow.log 报告只含select语句的慢

MySQL中查询日志与慢查询日志的基本学习教程_Mysql

一.查询日志   查询日志记录MySQL中所有的query,通过"--log[=file_name]"来打开该功能.由于记录了所有的query,包括所有的select,体积比较大,开启后对性能也有比较大的影响,所以请大家慎用该功能.一般只用于跟踪某些特殊的sql性能问题才会短暂打开该功能.默认的查询日志文件名为:hostname.log.  ----默认情况下查看是否启用查询日志: [root@node4 mysql5.5]# service mysql start Starting

mysql慢查询日志分析

第一步应该做的就是排查问题,找出瓶颈,所以,先从日志入手 开启慢查询日志 mysql>show variables like "%slow%"; 查看慢查询配置,没有则在my.cnf中添加,如下 log-slow-queries = /data/mysqldata/slowquery.log    #日志目录 long_query_time = 1                          #记录下查询时间查过1秒 log-queries-not-using-indexe

对MySQL慢查询日志进行分析的基本教程_Mysql

0.首先查看当前是否开启慢查询: (1)快速办法,运行sql语句 show VARIABLES like "%slow%" (2)直接去my.conf中查看. my.conf中的配置(放在[mysqld]下的下方加入) [mysqld] log-slow-queries = /usr/local/mysql/var/slowquery.log long_query_time = 1 #单位是秒 log-queries-not-using-indexes 使用sql语句来修改:不能按照m

【转载】MySQL慢查询日志总结

MySQL慢查询日志总结 2016-06-17 10:32 by 潇湘隐者, 1166 阅读, 1 评论, 收藏, 编辑 慢查询日志概念      MySQL的慢查询日志是MySQL提供的一种日志记录,它用来记录在MySQL中响应时间超过阀值的语句,具体指运行时间超过long_query_time值的SQL,则会被记录到慢查询日志中.long_query_time的默认值为10,意思是运行10S以上的语句.默认情况下,Mysql数据库并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是

MySQL 慢查询日志分析及可视化结果

MySQL 慢查询日志分析及可视化结果 MySQL 慢查询日志分析 pt-query-digest分析慢查询日志 pt-query-digest --report slow.log 报告最近半个小时的慢查询: pt-query-digest --report --since 1800s slow.log 报告一个时间段的慢查询: pt-query-digest --report --since '2013-02-10 21:48:59' --until '2013-02-16 02:33:50'

ELK logstash 处理MySQL慢查询日志的示例

在生产环境下,logstash 经常会遇到处理多种格式的日志,不同的日志格式,解析方法不同.下面来说说logstash处理多行日志的例子,对MySQL慢查询日志进行分析,这个经常遇到过,网络上疑问也很多. MySQL慢查询日志格式如下: # User@Host: ttlsa[ttlsa] @  [10.4.10.12]  Id: 69641319 # Query_time: 0.000148  Lock_time: 0.000023 Rows_sent: 0  Rows_examined: 20